runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: runsolver -W 300 -M 1124 -w /home/cbse/results/sarge-etch-lenny-squeeze/logs/3.runsolver.aptitude aptitude -s -y --without-recommends install wpp hibernate xtrlock gql-shell nettle-bin 

Enforcing wall clock limit (soft limit, will send signal-name then SIGKILL): 300 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.08 1.03 1.00 2/55 22696
/proc/meminfo: memFree=954284/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=3152 CPUtime=0
/proc/22696/stat : 22696 (runsolver) D 22695 22696 17863 34816 17863 4202560 80 0 0 0 0 0 0 0 20 0 1 0 28744510 3227648 101 18446744073709551615 134512640 134586868 4291147216 4291145184 4151444528 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/22696/statm: 788 101 69 19 0 73 0

[startup+0.129666 s]
/proc/loadavg: 1.08 1.03 1.00 2/55 22696
/proc/meminfo: memFree=954284/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=10112 CPUtime=0
/proc/22696/stat : 22696 (aptitude) D 22695 22696 17863 34816 17863 4202496 126 0 3 0 0 0 0 0 20 0 1 0 28744510 10354688 46 18446744073709551615 140573558796288 140573563103640 140736545005136 140736545002088 140573556655571 0 0 0 0 0 0 0 17 0 0 0 12 0 0
/proc/22696/statm: 2528 46 34 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 10112

[startup+0.20039 s]
/proc/loadavg: 1.08 1.03 1.00 2/55 22696
/proc/meminfo: memFree=954284/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=23840 CPUtime=0
/proc/22696/stat : 22696 (aptitude) D 22695 22696 17863 34816 17863 4202496 147 0 8 0 0 0 0 0 20 0 1 0 28744510 24412160 68 18446744073709551615 140573558796288 140573563103640 140736545005136 140736545001848 140573556654862 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/22696/statm: 5960 68 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300363 s]
/proc/loadavg: 1.08 1.03 1.00 2/55 22696
/proc/meminfo: memFree=954284/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=40832 CPUtime=0
/proc/22696/stat : 22696 (aptitude) D 22695 22696 17863 34816 17863 4202496 180 0 15 0 0 0 0 0 20 0 1 0 28744510 41811968 102 18446744073709551615 140573558796288 140573563103640 140736545005136 140736545001560 140573556655651 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/22696/statm: 10208 102 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.700337 s]
/proc/loadavg: 1.08 1.03 1.00 2/55 22696
/proc/meminfo: memFree=954284/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=100508 CPUtime=0.01
/proc/22696/stat : 22696 (aptitude) D 22695 22696 17863 34816 17863 4202496 2348 1706 32 4 0 1 0 0 20 0 1 0 28744510 102920192 2181 18446744073709551615 140573558796288 140573563103640 140736545005136 140736544996608 140573553846170 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/22696/statm: 25127 2181 1005 1052 0 1122 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 100508

[startup+1.5002 s]
/proc/loadavg: 1.08 1.03 1.00 1/56 22700
/proc/meminfo: memFree=945712/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=111108 CPUtime=0.34
/proc/22696/stat : 22696 (aptitude) R 22695 22696 17863 34816 17863 4202496 13211 1706 132 4 29 5 0 0 20 0 1 0 28744510 113774592 13136 18446744073709551615 140573558796288 140573563103640 140736545005136 140736544996248 140573553650924 0 134217728 4096 0 0 0 0 17 0 0 0 110 0 0
/proc/22696/statm: 27777 13136 9303 1052 0 3772 0
Current children cumulated CPU time (s) 0.34
Current children cumulated vsize (KiB) 111108

[startup+3.10021 s]
/proc/loadavg: 1.08 1.03 1.00 1/56 22700
/proc/meminfo: memFree=863996/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=132052 CPUtime=1.39
/proc/22696/stat : 22696 (aptitude) R 22695 22696 17863 34816 17863 4202496 19198 1706 132 4 126 13 0 0 20 0 2 0 28744510 135221248 16599 18446744073709551615 140573558796288 140573563103640 140736545005136 140736544992056 140573561824051 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 166 0 0
/proc/22696/statm: 33013 16599 9585 1052 0 9008 0
Current children cumulated CPU time (s) 1.39
Current children cumulated vsize (KiB) 132052
heavy processes:

Solver just ended. Dumping a history of the last processes samples

[startup+3.20742 s]
/proc/loadavg: 1.08 1.03 1.00 3/57 22701
/proc/meminfo: memFree=843528/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=132052 CPUtime=1.49
/proc/22696/stat : 22696 (aptitude) R 22695 22696 17863 34816 17863 4202496 19207 1706 132 4 136 13 0 0 20 0 2 0 28744510 135221248 16608 18446744073709551615 140573558796288 140573563103640 140736545005136 140736544992056 140573560431767 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 166 0 0
/proc/22696/statm: 33013 16608 9585 1052 0 9008 0
[pid=22696/tid=22701] ppid=22695 vsize=132052 CPUtime=0
/proc/22696/task/22701/stat : 22701 (aptitude) S 22695 22696 17863 34816 17863 4202560 4 1706 0 4 0 0 0 0 20 0 2 0 28744749 135221248 16608 18446744073709551615 140573558796288 140573563103640 140736545005136 140573449623552 140573527540436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 132052

[startup+4.00024 s]
/proc/loadavg: 1.08 1.03 1.00 2/57 22701
/proc/meminfo: memFree=843404/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=133680 CPUtime=2.25
/proc/22696/stat : 22696 (aptitude) R 22695 22696 17863 34816 17863 4202496 20183 2202 133 5 211 14 0 0 20 0 2 0 28744510 136888320 16771 18446744073709551615 140573558796288 140573563103640 140736545005136 140736544991840 140573561504373 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0
/proc/22696/statm: 33420 16771 9637 1052 0 9415 0
[pid=22696/tid=22701] ppid=22695 vsize=133680 CPUtime=0
/proc/22696/task/22701/stat : 22701 (aptitude) S 22695 22696 17863 34816 17863 4202560 6 2202 0 5 0 0 0 0 20 0 2 0 28744749 136888320 16771 18446744073709551615 140573558796288 140573563103640 140736545005136 140573449623552 140573527540436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 2.25
Current children cumulated vsize (KiB) 133680

[startup+4.80035 s]
/proc/loadavg: 1.08 1.03 1.00 2/57 22702
/proc/meminfo: memFree=842536/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=142664 CPUtime=3.04
/proc/22696/stat : 22696 (aptitude) S 22695 22696 17863 34816 17863 4202496 23951 2202 133 5 289 15 0 0 20 0 2 0 28744510 146087936 19382 18446744073709551615 140573558796288 140573563103640 140736545005136 140736544996896 140573527541323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0
/proc/22696/statm: 35666 19382 9693 1052 0 11661 0
[pid=22696/tid=22701] ppid=22695 vsize=142664 CPUtime=0.4
/proc/22696/task/22701/stat : 22701 (aptitude) D 22695 22696 17863 34816 17863 4202560 3763 2202 0 5 38 2 0 0 20 0 2 0 28744749 146087936 19382 18446744073709551615 140573558796288 140573563103640 140736545005136 140573449615240 140573561754928 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 142664

[startup+5.20032 s]
/proc/loadavg: 1.08 1.03 1.00 2/57 22702
/proc/meminfo: memFree=842536/1022884 swapFree=0/0
[pid=22696] ppid=22695 vsize=75956 CPUtime=3.3
/proc/22696/stat : 22696 (aptitude) D 22695 22696 17863 34816 17863 4202496 26633 2701 160 5 309 20 0 1 20 0 1 0 28744510 77778944 2809 18446744073709551615 140573558796288 140573563103640 140736545005136 140736545004208 140573524956080 0 134217728 4096 0 0 0 0 17 0 0 0 181 0 0
/proc/22696/statm: 18989 2809 1520 1052 0 3245 0
Current children cumulated CPU time (s) 3.3
Current children cumulated vsize (KiB) 75956

Child status: 0
Real time (s): 5.22694
CPU time (s): 3.32021
CPU user time (s): 3.10419
CPU system time (s): 0.216013
CPU usage (%): 63.521
Max. virtual memory (cumulated for all children) (KiB): 142824

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.10419
system time used= 0.216013
maximum resident set size= 77892
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 29353
page faults= 168
swaps= 0
block input operations= 169520
block output operations= 8
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1650
involuntary context switches= 108

runsolver used 0.016001 second user time and 0.016001 second system time

The end