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/46.runsolver.aptitude aptitude -s -y --without-recommends install gtkguitune libwrap-ruby1.8 t1lib-bin tct libdb3-util 

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.28 1.10 1.02 2/55 23318
/proc/meminfo: memFree=962976/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=3152 CPUtime=0
/proc/23318/stat : 23318 (runsolver) R 23317 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28916471 3227648 33 18446744073709551615 134512640 134586868 4288780576 4288778624 4151378992 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23318/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.110319 s]
/proc/loadavg: 1.28 1.10 1.02 2/55 23318
/proc/meminfo: memFree=962976/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=4628 CPUtime=0
/proc/23318/stat : 23318 (aptitude) D 23317 23318 17863 34816 17863 4202496 114 0 3 0 0 0 0 0 20 0 1 0 28916471 4739072 36 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403606120 140634269934039 0 0 0 0 0 0 0 17 0 0 0 9 0 0
/proc/23318/statm: 1157 36 28 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 4628

[startup+0.200253 s]
/proc/loadavg: 1.28 1.10 1.02 2/55 23318
/proc/meminfo: memFree=962976/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=23840 CPUtime=0
/proc/23318/stat : 23318 (aptitude) D 23317 23318 17863 34816 17863 4202496 144 0 9 0 0 0 0 0 20 0 1 0 28916471 24412160 67 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403605240 140634269938446 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23318/statm: 5960 67 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300392 s]
/proc/loadavg: 1.28 1.10 1.02 2/55 23318
/proc/meminfo: memFree=962976/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=40832 CPUtime=0
/proc/23318/stat : 23318 (aptitude) D 23317 23318 17863 34816 17863 4202496 176 0 16 0 0 0 0 0 20 0 1 0 28916471 41811968 100 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403604952 140634269939235 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/23318/statm: 10208 100 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.700323 s]
/proc/loadavg: 1.28 1.10 1.02 2/55 23318
/proc/meminfo: memFree=962976/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=100508 CPUtime=0.02
/proc/23318/stat : 23318 (aptitude) D 23317 23318 17863 34816 17863 4202496 2573 1705 37 4 1 0 0 1 20 0 1 0 28916471 102920192 2411 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403600000 140634267129754 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/23318/statm: 25127 2411 1237 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+1.50033 s]
/proc/loadavg: 1.28 1.10 1.02 1/56 23322
/proc/meminfo: memFree=955396/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=100508 CPUtime=0.07
/proc/23318/stat : 23318 (aptitude) D 23317 23318 17863 34816 17863 4202496 8505 1705 177 4 4 2 0 1 20 0 1 0 28916471 102920192 8483 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403599792 140634266924945 0 134217728 4096 0 0 0 0 17 0 0 0 138 0 0
/proc/23318/statm: 25127 8483 7309 1052 0 1122 0
Current children cumulated CPU time (s) 0.07
Current children cumulated vsize (KiB) 100508

[startup+3.10019 s]
/proc/loadavg: 1.26 1.10 1.02 2/56 23322
/proc/meminfo: memFree=920056/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=123288 CPUtime=0.95
/proc/23318/stat : 23318 (aptitude) R 23317 23318 17863 34816 17863 4202496 16830 1705 198 4 80 14 0 1 20 0 2 0 28916471 126246912 14302 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403604312 140634266916464 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 212 0 0
/proc/23318/statm: 30822 14302 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.95
Current children cumulated vsize (KiB) 123288
heavy processes:

[startup+6.30031 s]
/proc/loadavg: 1.26 1.10 1.02 2/57 23324
/proc/meminfo: memFree=832628/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=157856 CPUtime=4.08
/proc/23318/stat : 23318 (aptitude) S 23317 23318 17863 34816 17863 4202496 26730 2200 198 6 387 20 0 1 20 0 2 0 28916471 161644544 23175 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403600288 140634240824907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 216 0 0
/proc/23318/statm: 39464 23175 9700 1052 0 15459 0
[pid=23318/tid=23323] ppid=23317 vsize=157856 CPUtime=1.07
/proc/23318/task/23323/stat : 23323 (aptitude) R 23317 23318 17863 34816 17863 4202560 6333 2200 0 6 105 1 0 1 20 0 2 0 28916758 161644544 23175 18446744073709551615 140634272079872 140634276387224 140734403608528 140634162900792 140634274906673 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.08
Current children cumulated vsize (KiB) 157856
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.22 1.10 1.02 2/57 23324
/proc/meminfo: memFree=771992/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=271640 CPUtime=10.44
/proc/23318/stat : 23318 (aptitude) S 23317 23318 17863 34816 17863 4202496 39594 2200 198 6 1019 24 0 1 20 0 2 0 28916471 278159360 35241 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403600288 140634240824907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 216 0 0
/proc/23318/statm: 67910 35241 9700 1052 0 43905 0
[pid=23318/tid=23323] ppid=23317 vsize=271640 CPUtime=7.44
/proc/23318/task/23323/stat : 23323 (aptitude) R 23317 23318 17863 34816 17863 4202560 19196 2200 0 6 737 6 0 1 20 0 2 0 28916758 278159360 35241 18446744073709551615 140634272079872 140634276387224 140734403608528 140634162898536 140634274930047 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.44
Current children cumulated vsize (KiB) 271640

[startup+25.5003 s]
/proc/loadavg: 1.18 1.09 1.02 2/57 23324
/proc/meminfo: memFree=670808/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=370048 CPUtime=23.18
/proc/23318/stat : 23318 (aptitude) S 23317 23318 17863 34816 17863 4202496 64640 2200 198 6 2280 37 0 1 20 0 2 0 28916471 378929152 59820 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403600288 140634240824907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 216 0 0
/proc/23318/statm: 92512 59820 9700 1052 0 68507 0
[pid=23318/tid=23323] ppid=23317 vsize=370048 CPUtime=20.17
/proc/23318/task/23323/stat : 23323 (aptitude) R 23317 23318 17863 34816 17863 4202560 44242 2200 0 6 1998 18 0 1 20 0 2 0 28916758 378929152 59820 18446744073709551615 140634272079872 140634276387224 140734403608528 140634162898504 140634238013037 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.18
Current children cumulated vsize (KiB) 370048

[startup+51.1003 s]
/proc/loadavg: 1.12 1.08 1.02 2/57 23324
/proc/meminfo: memFree=412392/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=631572 CPUtime=48.66
/proc/23318/stat : 23318 (aptitude) S 23317 23318 17863 34816 17863 4202496 130027 2200 198 6 4793 72 0 1 20 0 2 0 28916471 646729728 125176 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403600288 140634240824907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 216 0 0
/proc/23318/statm: 157893 125176 9716 1052 0 133888 0
[pid=23318/tid=23323] ppid=23317 vsize=631572 CPUtime=45.66
/proc/23318/task/23323/stat : 23323 (aptitude) R 23317 23318 17863 34816 17863 4202560 109623 2200 0 6 4511 54 0 1 20 0 2 0 28916758 646729728 125176 18446744073709551615 140634272079872 140634276387224 140734403608528 140634162898808 140634238392348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.66
Current children cumulated vsize (KiB) 631572

[startup+102.3 s]
/proc/loadavg: 1.11 1.08 1.02 2/57 23324
/proc/meminfo: memFree=9264/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=1146064 CPUtime=98.39
/proc/23318/stat : 23318 (aptitude) S 23317 23318 17863 34816 17863 4202496 258686 2200 246 6 9690 148 0 1 20 0 2 0 28916471 1173569536 244691 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403600288 140634240824907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 217 0 0
/proc/23318/statm: 286516 244691 9680 1052 0 262511 0
[pid=23318/tid=23323] ppid=23317 vsize=1146064 CPUtime=95.37
/proc/23318/task/23323/stat : 23323 (aptitude) R 23317 23318 17863 34816 17863 4202560 238271 2200 43 6 9407 129 0 1 20 0 2 0 28916758 1173569536 244691 18446744073709551615 140634272079872 140634276387224 140734403608528 140634162898504 140634274712609 0 134217728 4096 0 0 0 0 -1 0 0 0 88 0 0
Current children cumulated CPU time (s) 98.39
Current children cumulated vsize (KiB) 1146064



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+102.9 s]
/proc/loadavg: 1.11 1.08 1.02 2/57 23324
/proc/meminfo: memFree=10124/1022884 swapFree=0/0
[pid=23318] ppid=23317 vsize=1151344 CPUtime=98.91
/proc/23318/stat : 23318 (aptitude) S 23317 23318 17863 34816 17863 4202496 260000 2200 252 6 9742 148 0 1 20 0 2 0 28916471 1178976256 244611 18446744073709551615 140634272079872 140634276387224 140734403608528 140734403600288 140634240824907 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 217 0 0
/proc/23318/statm: 287836 244611 9676 1052 0 263831 0
[pid=23318/tid=23323] ppid=23317 vsize=1151344 CPUtime=95.9
/proc/23318/task/23323/stat : 23323 (aptitude) R 23317 23318 17863 34816 17863 4202560 239585 2200 49 6 9459 130 0 1 20 0 2 0 28916758 1178976256 244611 18446744073709551615 140634272079872 140634276387224 140734403608528 140634162900568 140634274853953 0 134217728 4096 0 0 0 0 -1 0 0 0 91 0 0
Current children cumulated CPU time (s) 98.91
Current children cumulated vsize (KiB) 1151344

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

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

Child ended because it received signal 15 (SIGTERM)
Real time (s): 103.002
CPU time (s): 99.0182
CPU user time (s): 97.4461
CPU system time (s): 1.5721
CPU usage (%): 96.1324
Max. virtual memory (cumulated for all children) (KiB): 1151344

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 97.4461
system time used= 1.5721
maximum resident set size= 981348
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262241
page faults= 258
swaps= 0
block input operations= 187408
block output operations= 88
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2129
involuntary context switches= 2405

runsolver used 0.004 second user time and 0.48403 second system time

The end