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/28.runsolver.aptitude aptitude -s -y --without-recommends install libpils-dev scigraphica wogerman bluez-pcmcia-support libperl4caml-ocaml-dev 

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

[startup+0 s]
/proc/loadavg: 1.03 1.07 1.02 2/55 23145
/proc/meminfo: memFree=864088/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=3152 CPUtime=0
/proc/23145/stat : 23145 (runsolver) R 23144 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28834126 3227648 32 18446744073709551615 134512640 134586868 4288160528 4288158576 4151301168 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.140295 s]
/proc/loadavg: 1.03 1.07 1.02 2/55 23145
/proc/meminfo: memFree=864088/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=100508 CPUtime=0.12
/proc/23145/stat : 23145 (aptitude) R 23144 23145 17863 34816 17863 4202496 10582 1710 0 0 10 2 0 0 20 0 1 0 28834126 102920192 10380 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055296 140199802126761 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 25127 10380 9206 1052 0 1122 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 100508

[startup+0.200287 s]
/proc/loadavg: 1.03 1.07 1.02 2/55 23145
/proc/meminfo: memFree=864088/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=100508 CPUtime=0.18
/proc/23145/stat : 23145 (aptitude) R 23144 23145 17863 34816 17863 4202496 10608 1710 0 0 16 2 0 0 20 0 1 0 28834126 102920192 10406 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055296 140199801569972 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 25127 10406 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300275 s]
/proc/loadavg: 1.03 1.07 1.02 2/55 23145
/proc/meminfo: memFree=864088/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=111108 CPUtime=0.28
/proc/23145/stat : 23145 (aptitude) R 23144 23145 17863 34816 17863 4202496 12540 1710 0 0 26 2 0 0 20 0 1 0 28834126 113774592 12330 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055624 140199808857708 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 27777 12330 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700209 s]
/proc/loadavg: 1.03 1.07 1.02 2/55 23145
/proc/meminfo: memFree=864088/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=123288 CPUtime=0.68
/proc/23145/stat : 23145 (aptitude) R 23144 23145 17863 34816 17863 4202496 17030 1710 0 0 62 6 0 0 20 0 2 0 28834126 126246912 14302 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045059816 140199801569458 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 30822 14302 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.03 1.07 1.02 2/57 23150
/proc/meminfo: memFree=835792/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=132432 CPUtime=1.48
/proc/23145/stat : 23145 (aptitude) R 23144 23145 17863 34816 17863 4202496 19447 1710 0 0 141 7 0 0 20 0 2 0 28834126 135610368 16715 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045054384 140199772651888 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 33108 16715 9585 1052 0 9103 0
[pid=23145/tid=23150] ppid=23144 vsize=132432 CPUtime=0
/proc/23145/task/23150/stat : 23150 (aptitude) S 23144 23145 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 28834192 135610368 16715 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697553408 140199775470292 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 132432

[startup+3.10024 s]
/proc/loadavg: 1.03 1.07 1.02 2/57 23151
/proc/meminfo: memFree=834544/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=133844 CPUtime=3.08
/proc/23145/stat : 23145 (aptitude) R 23144 23145 17863 34816 17863 4202496 20637 2208 0 0 296 11 0 1 20 0 2 0 28834126 137056256 16956 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045050736 140199808927515 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 33461 16956 9644 1052 0 9456 0
[pid=23145/tid=23150] ppid=23144 vsize=133844 CPUtime=0.01
/proc/23145/task/23150/stat : 23150 (aptitude) S 23144 23145 17863 34816 17863 4202560 6 2208 0 0 0 0 0 1 20 0 2 0 28834192 137056256 16956 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697553408 140199775470292 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 133844

[startup+6.30024 s]
/proc/loadavg: 1.03 1.06 1.02 2/57 23151
/proc/meminfo: memFree=796484/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=248092 CPUtime=6.26
/proc/23145/stat : 23145 (aptitude) S 23144 23145 17863 34816 17863 4202496 33330 2208 0 0 608 17 0 1 20 0 2 0 28834126 254046208 29357 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055792 140199775471179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 62023 29357 9700 1052 0 38018 0
[pid=23145/tid=23150] ppid=23144 vsize=248092 CPUtime=3.14
/proc/23145/task/23150/stat : 23150 (aptitude) R 23144 23145 17863 34816 17863 4202560 12692 2208 0 0 307 6 0 1 20 0 2 0 28834192 254046208 29357 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697546936 140199809372581 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 248092

[startup+12.7002 s]
/proc/loadavg: 1.02 1.06 1.01 2/57 23151
/proc/meminfo: memFree=749860/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=285844 CPUtime=12.63
/proc/23145/stat : 23145 (aptitude) S 23144 23145 17863 34816 17863 4202496 43327 2208 0 0 1240 22 0 1 20 0 2 0 28834126 292704256 38784 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055792 140199775471179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 71461 38784 9700 1052 0 47456 0
[pid=23145/tid=23150] ppid=23144 vsize=285844 CPUtime=9.5
/proc/23145/task/23150/stat : 23150 (aptitude) R 23144 23145 17863 34816 17863 4202560 22689 2208 0 0 938 11 0 1 20 0 2 0 28834192 292704256 38784 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697544728 140199809408864 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 285844

[startup+25.5003 s]
/proc/loadavg: 1.02 1.06 1.01 2/57 23151
/proc/meminfo: memFree=645088/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=389204 CPUtime=25.37
/proc/23145/stat : 23145 (aptitude) S 23144 23145 17863 34816 17863 4202496 69581 2208 0 0 2500 36 0 1 20 0 2 0 28834126 398544896 64593 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055792 140199775471179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 97301 64593 9700 1052 0 73296 0
[pid=23145/tid=23150] ppid=23144 vsize=389204 CPUtime=22.24
/proc/23145/task/23150/stat : 23150 (aptitude) R 23144 23145 17863 34816 17863 4202560 48943 2208 0 0 2199 24 0 1 20 0 2 0 28834192 398544896 64593 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697544728 140199807505360 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 389204

[startup+51.1003 s]
/proc/loadavg: 1.01 1.05 1.01 2/57 23159
/proc/meminfo: memFree=466776/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=566700 CPUtime=50.83
/proc/23145/stat : 23145 (aptitude) S 23144 23145 17863 34816 17863 4202496 114008 2208 0 0 5026 56 0 1 20 0 2 0 28834126 580300800 108950 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055792 140199775471179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 141675 108950 9714 1052 0 117670 0
[pid=23145/tid=23150] ppid=23144 vsize=566700 CPUtime=47.71
/proc/23145/task/23150/stat : 23150 (aptitude) R 23144 23145 17863 34816 17863 4202560 93363 2208 0 0 4725 45 0 1 20 0 2 0 28834192 580300800 108950 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697546936 140199809434181 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.83
Current children cumulated vsize (KiB) 566700

[startup+102.3 s]
/proc/loadavg: 1.00 1.04 1.01 2/57 23159
/proc/meminfo: memFree=191620/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=837900 CPUtime=101.8
/proc/23145/stat : 23145 (aptitude) S 23144 23145 17863 34816 17863 4202496 181736 2208 0 0 10085 94 0 1 20 0 2 0 28834126 858009600 176627 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055792 140199775471179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 209475 176627 9714 1052 0 185470 0
[pid=23145/tid=23150] ppid=23144 vsize=837900 CPUtime=98.67
/proc/23145/task/23150/stat : 23150 (aptitude) R 23144 23145 17863 34816 17863 4202560 161091 2208 0 0 9783 83 0 1 20 0 2 0 28834192 858009600 176627 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697544856 140199809372442 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 101.8
Current children cumulated vsize (KiB) 837900



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+142.8 s]
/proc/loadavg: 1.14 1.07 1.01 1/57 23159
/proc/meminfo: memFree=8844/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=1151292 CPUtime=140.11
/proc/23145/stat : 23145 (aptitude) S 23144 23145 17863 34816 17863 4202496 260255 2208 185 0 13866 144 0 1 20 0 2 0 28834126 1178923008 246896 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055792 140199775471179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 287823 246896 9395 1052 0 263818 0
[pid=23145/tid=23150] ppid=23144 vsize=1151292 CPUtime=136.97
/proc/23145/task/23150/stat : 23150 (aptitude) D 23144 23145 17863 34816 17863 4202560 239610 2208 185 0 13563 133 0 1 20 0 2 0 28834192 1178923008 246896 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697545080 140199809363842 0 134217728 4096 0 0 0 0 -1 0 0 0 170 0 0
Current children cumulated CPU time (s) 140.11
Current children cumulated vsize (KiB) 1151292

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

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

[startup+142.8 s]
/proc/loadavg: 1.14 1.07 1.01 1/57 23159
/proc/meminfo: memFree=8844/1022884 swapFree=0/0
[pid=23145] ppid=23144 vsize=1151292 CPUtime=140.11
/proc/23145/stat : 23145 (aptitude) S 23144 23145 17863 34816 17863 4202496 260255 2208 185 0 13866 144 0 1 20 0 2 0 28834126 1178923008 246896 18446744073709551615 140199806726144 140199811033496 140735045064032 140735045055792 140199775471179 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23145/statm: 287823 246896 9395 1052 0 263818 0
[pid=23145/tid=23150] ppid=23144 vsize=1151292 CPUtime=136.97
/proc/23145/task/23150/stat : 23150 (aptitude) D 23144 23145 17863 34816 17863 4202560 239610 2208 185 0 13563 133 0 1 20 0 2 0 28834192 1178923008 246896 18446744073709551615 140199806726144 140199811033496 140735045064032 140199697545080 140199809363842 0 134217728 4096 0 0 0 0 -1 0 0 0 170 0 0
Current children cumulated CPU time (s) 140.11
Current children cumulated vsize (KiB) 1151292

Child ended because it received signal 15 (SIGTERM)
Real time (s): 142.935
CPU time (s): 140.221
CPU user time (s): 138.709
CPU system time (s): 1.51209
CPU usage (%): 98.1012
Max. virtual memory (cumulated for all children) (KiB): 1151292

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 138.709
system time used= 1.51209
maximum resident set size= 987852
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262529
page faults= 186
swaps= 0
block input operations= 6232
block output operations= 152
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 560
involuntary context switches= 3065

runsolver used 0.212013 second user time and 0.448028 second system time

The end