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/97.runsolver.aptitude aptitude -s -y --without-recommends install mimedefang openthreads-doc alsa-modules-2.4-686-smp kde-i18n-cy libkeynote0 

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.15 1.09 1.04 2/55 24240
/proc/meminfo: memFree=959504/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=3152 CPUtime=0
/proc/24240/stat : 24240 (runsolver) R 24239 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29179293 3227648 32 18446744073709551615 134512640 134586868 4291500880 4291498928 4152087600 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24240/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.116623 s]
/proc/loadavg: 1.15 1.09 1.04 2/55 24240
/proc/meminfo: memFree=959504/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=7872 CPUtime=0
/proc/24240/stat : 24240 (aptitude) D 24239 24240 17863 34816 17863 4202496 118 0 3 0 0 0 0 0 20 0 1 0 29179293 8060928 40 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586914904 140496591369763 0 0 0 0 0 0 0 17 0 0 0 9 0 0
/proc/24240/statm: 1968 40 30 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 7872

[startup+0.200411 s]
/proc/loadavg: 1.15 1.09 1.04 2/55 24240
/proc/meminfo: memFree=959504/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=28716 CPUtime=0
/proc/24240/stat : 24240 (aptitude) D 24239 24240 17863 34816 17863 4202496 155 0 11 0 0 0 0 0 20 0 1 0 29179293 29405184 78 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586914520 140496591369763 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/24240/statm: 7179 78 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.300445 s]
/proc/loadavg: 1.15 1.09 1.04 2/55 24240
/proc/meminfo: memFree=959504/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=44448 CPUtime=0
/proc/24240/stat : 24240 (aptitude) D 24239 24240 17863 34816 17863 4202496 180 0 17 0 0 0 0 0 20 0 1 0 29179293 45514752 105 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586914088 140496591369606 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/24240/statm: 11112 105 65 1052 0 61 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 44448

[startup+0.700333 s]
/proc/loadavg: 1.15 1.09 1.04 2/55 24240
/proc/meminfo: memFree=959504/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=100508 CPUtime=0.01
/proc/24240/stat : 24240 (aptitude) D 24239 24240 17863 34816 17863 4202496 2549 1705 47 4 0 1 0 0 20 0 1 0 29179293 102920192 2398 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909376 140496588560282 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/24240/statm: 25127 2398 1223 1052 0 1122 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 100508

[startup+1.5003 s]
/proc/loadavg: 1.13 1.09 1.04 1/56 24244
/proc/meminfo: memFree=951064/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=100508 CPUtime=0.03
/proc/24240/stat : 24240 (aptitude) D 24239 24240 17863 34816 17863 4202496 6127 1705 184 4 1 2 0 0 20 0 1 0 29179293 102920192 6113 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909376 140496588357912 0 134217728 4096 0 0 0 0 17 0 0 0 142 0 0
/proc/24240/statm: 25127 6113 4938 1052 0 1122 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 100508

[startup+3.1003 s]
/proc/loadavg: 1.13 1.09 1.04 2/56 24244
/proc/meminfo: memFree=936432/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=119772 CPUtime=0.67
/proc/24240/stat : 24240 (aptitude) D 24239 24240 17863 34816 17863 4202496 16253 1705 255 4 58 9 0 0 20 0 1 0 29179293 122646528 14787 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586907336 140496562266480 0 134217728 4096 0 0 0 0 17 0 0 0 237 0 0
/proc/24240/statm: 29943 14787 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.67
Current children cumulated vsize (KiB) 119772
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.12 1.09 1.04 2/57 24246
/proc/meminfo: memFree=841316/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=146404 CPUtime=3.81
/proc/24240/stat : 24240 (aptitude) S 24239 24240 17863 34816 17863 4202496 23947 2203 255 6 362 19 0 0 20 0 2 0 29179293 149917696 20319 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909664 140496562255435 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24240/statm: 36601 20319 9699 1052 0 12596 0
[pid=24240/tid=24245] ppid=24239 vsize=146404 CPUtime=0.63
/proc/24240/task/24245/stat : 24245 (aptitude) R 24239 24240 17863 34816 17863 4202560 3540 2203 0 6 62 1 0 0 20 0 2 0 29179605 149917696 20319 18446744073709551615 140496593510400 140496597817752 140733586917904 140496484331128 140496596218086 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.81
Current children cumulated vsize (KiB) 146404
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.11 1.09 1.04 2/57 24246
/proc/meminfo: memFree=777952/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=266860 CPUtime=10.18
/proc/24240/stat : 24240 (aptitude) S 24239 24240 17863 34816 17863 4202496 37850 2203 255 6 995 23 0 0 20 0 2 0 29179293 273264640 34044 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909664 140496562255435 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24240/statm: 66715 34044 9700 1052 0 42710 0
[pid=24240/tid=24245] ppid=24239 vsize=266860 CPUtime=7
/proc/24240/task/24245/stat : 24245 (aptitude) R 24239 24240 17863 34816 17863 4202560 17442 2203 0 6 695 5 0 0 20 0 2 0 29179605 273264640 34044 18446744073709551615 140496593510400 140496597817752 140733586917904 140496484331192 140496596255187 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.18
Current children cumulated vsize (KiB) 266860

[startup+25.5003 s]
/proc/loadavg: 1.10 1.08 1.04 2/57 24246
/proc/meminfo: memFree=669824/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=371652 CPUtime=22.92
/proc/24240/stat : 24240 (aptitude) S 24239 24240 17863 34816 17863 4202496 64484 2203 255 6 2261 31 0 0 20 0 2 0 29179293 380571648 60228 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909664 140496562255435 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24240/statm: 92913 60228 9714 1052 0 68908 0
[pid=24240/tid=24245] ppid=24239 vsize=371652 CPUtime=19.74
/proc/24240/task/24245/stat : 24245 (aptitude) R 24239 24240 17863 34816 17863 4202560 44069 2203 0 6 1960 14 0 0 20 0 2 0 29179605 380571648 60228 18446744073709551615 140496593510400 140496597817752 140733586917904 140496484331192 140496595721306 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.92
Current children cumulated vsize (KiB) 371652

[startup+51.1003 s]
/proc/loadavg: 1.06 1.07 1.04 2/57 24246
/proc/meminfo: memFree=511476/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=530516 CPUtime=48.41
/proc/24240/stat : 24240 (aptitude) S 24239 24240 17863 34816 17863 4202496 104216 2203 255 6 4786 55 0 0 20 0 2 0 29179293 543248384 99876 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909664 140496562255435 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24240/statm: 132629 99876 9714 1052 0 108624 0
[pid=24240/tid=24245] ppid=24239 vsize=530516 CPUtime=45.22
/proc/24240/task/24245/stat : 24245 (aptitude) R 24239 24240 17863 34816 17863 4202560 83801 2203 0 6 4485 37 0 0 20 0 2 0 29179605 543248384 99876 18446744073709551615 140496593510400 140496597817752 140733586917904 140496484328984 140496562246065 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.41
Current children cumulated vsize (KiB) 530516

[startup+102.3 s]
/proc/loadavg: 1.02 1.06 1.03 2/57 24246
/proc/meminfo: memFree=143816/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=895488 CPUtime=99.37
/proc/24240/stat : 24240 (aptitude) S 24239 24240 17863 34816 17863 4202496 195447 2203 255 6 9839 98 0 0 20 0 2 0 29179293 916979712 191034 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909664 140496562255435 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24240/statm: 223872 191034 9715 1052 0 199867 0
[pid=24240/tid=24245] ppid=24239 vsize=895488 CPUtime=96.18
/proc/24240/task/24245/stat : 24245 (aptitude) R 24239 24240 17863 34816 17863 4202560 175032 2203 0 6 9537 81 0 0 20 0 2 0 29179605 916979712 191034 18446744073709551615 140496593510400 140496597817752 140733586917904 140496484331144 140496562245920 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 99.37
Current children cumulated vsize (KiB) 895488



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+145.7 s]
/proc/loadavg: 1.19 1.10 1.04 1/57 24246
/proc/meminfo: memFree=9016/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=1151308 CPUtime=139.83
/proc/24240/stat : 24240 (aptitude) S 24239 24240 17863 34816 17863 4202496 259761 2203 477 6 13855 128 0 0 20 0 2 0 29179293 1178939392 244164 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909664 140496562255435 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24240/statm: 287827 244140 9047 1052 0 263822 0
[pid=24240/tid=24245] ppid=24239 vsize=1151308 CPUtime=136.63
/proc/24240/task/24245/stat : 24245 (aptitude) D 24239 24240 17863 34816 17863 4202560 239334 2203 218 6 13553 110 0 0 20 0 2 0 29179605 1178939392 244140 18446744073709551615 140496593510400 140496597817752 140733586917904 140496484331320 140496551010824 0 134217728 4096 0 0 0 0 -1 0 0 0 234 0 0
Current children cumulated CPU time (s) 139.83
Current children cumulated vsize (KiB) 1151308

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

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

[startup+145.7 s]
/proc/loadavg: 1.19 1.10 1.04 1/57 24246
/proc/meminfo: memFree=9016/1022884 swapFree=0/0
[pid=24240] ppid=24239 vsize=1151308 CPUtime=139.83
/proc/24240/stat : 24240 (aptitude) S 24239 24240 17863 34816 17863 4202496 259761 2203 477 6 13855 128 0 0 20 0 2 0 29179293 1178939392 244164 18446744073709551615 140496593510400 140496597817752 140733586917904 140733586909664 140496562255435 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24240/statm: 287827 244140 9047 1052 0 263822 0
[pid=24240/tid=24245] ppid=24239 vsize=1151308 CPUtime=136.63
/proc/24240/task/24245/stat : 24245 (aptitude) D 24239 24240 17863 34816 17863 4202560 239334 2203 218 6 13553 110 0 0 20 0 2 0 29179605 1178939392 244140 18446744073709551615 140496593510400 140496597817752 140733586917904 140496484331320 140496551010824 0 134217728 4096 0 0 0 0 -1 0 0 0 234 0 0
Current children cumulated CPU time (s) 139.83
Current children cumulated vsize (KiB) 1151308

Child ended because it received signal 15 (SIGTERM)
Real time (s): 145.828
CPU time (s): 139.937
CPU user time (s): 138.573
CPU system time (s): 1.36408
CPU usage (%): 95.9604
Max. virtual memory (cumulated for all children) (KiB): 1151308

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 138.573
system time used= 1.36408
maximum resident set size= 977528
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 261969
page faults= 484
swaps= 0
block input operations= 188704
block output operations= 72
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2293
involuntary context switches= 3041

runsolver used 0.180011 second user time and 0.504031 second system time

The end