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/49.runsolver.aptitude aptitude -s -y --without-recommends install pathogen contact-lookup-applet libdbd-pg-perl exim gnusound 

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.06 1.07 1.01 2/55 23345
/proc/meminfo: memFree=869228/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=3152 CPUtime=0
/proc/23345/stat : 23345 (runsolver) R 23344 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28930487 3227648 33 18446744073709551615 134512640 134586868 4293212384 4293210432 4152091696 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.161712 s]
/proc/loadavg: 1.06 1.07 1.01 2/55 23345
/proc/meminfo: memFree=869228/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=100508 CPUtime=0.14
/proc/23345/stat : 23345 (aptitude) R 23344 23345 17863 34816 17863 4202496 10598 1708 0 0 11 3 0 0 20 0 1 0 28930487 102920192 10399 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754320 140027787681724 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 25127 10399 9224 1052 0 1122 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 100508

[startup+0.200282 s]
/proc/loadavg: 1.06 1.07 1.01 2/55 23345
/proc/meminfo: memFree=869228/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=100508 CPUtime=0.19
/proc/23345/stat : 23345 (aptitude) R 23344 23345 17863 34816 17863 4202496 10606 1708 0 0 15 4 0 0 20 0 1 0 28930487 102920192 10407 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754320 140027824940394 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 100508

[startup+0.300271 s]
/proc/loadavg: 1.06 1.07 1.01 2/55 23345
/proc/meminfo: memFree=869228/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=111108 CPUtime=0.28
/proc/23345/stat : 23345 (aptitude) R 23344 23345 17863 34816 17863 4202496 11737 1708 0 0 24 4 0 0 20 0 1 0 28930487 113774592 11530 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754648 140027832231523 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 27777 11530 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700202 s]
/proc/loadavg: 1.06 1.07 1.01 2/55 23345
/proc/meminfo: memFree=869228/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=123288 CPUtime=0.68
/proc/23345/stat : 23345 (aptitude) R 23344 23345 17863 34816 17863 4202496 17029 1708 0 0 60 8 0 0 20 0 2 0 28930487 126246912 14303 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307758840 140027824945283 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 30822 14303 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.06 1.07 1.01 2/57 23350
/proc/meminfo: memFree=840948/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=132412 CPUtime=1.47
/proc/23345/stat : 23345 (aptitude) R 23344 23345 17863 34816 17863 4202496 19440 1708 0 0 138 9 0 0 20 0 2 0 28930487 135589888 16709 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307753408 140027831728311 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 33103 16709 9585 1052 0 9098 0
[pid=23345/tid=23350] ppid=23344 vsize=132412 CPUtime=0
/proc/23345/task/23350/stat : 23350 (aptitude) S 23344 23345 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 28930553 135589888 16709 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720927232 140027798844116 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 132412

[startup+3.10024 s]
/proc/loadavg: 1.06 1.07 1.01 2/57 23351
/proc/meminfo: memFree=839824/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=133820 CPUtime=3.08
/proc/23345/stat : 23345 (aptitude) R 23344 23345 17863 34816 17863 4202496 20620 2207 0 0 294 13 1 0 20 0 2 0 28930487 137031680 16947 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307749872 140027824927712 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 33455 16947 9644 1052 0 9450 0
[pid=23345/tid=23350] ppid=23344 vsize=133820 CPUtime=0.01
/proc/23345/task/23350/stat : 23350 (aptitude) S 23344 23345 17863 34816 17863 4202560 6 2207 0 0 0 0 1 0 20 0 2 0 28930553 137031680 16947 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720927232 140027798844116 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) 133820

[startup+6.30025 s]
/proc/loadavg: 1.06 1.07 1.01 2/57 23351
/proc/meminfo: memFree=796308/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=245584 CPUtime=6.26
/proc/23345/stat : 23345 (aptitude) S 23344 23345 17863 34816 17863 4202496 33305 2207 0 0 609 16 1 0 20 0 2 0 28930487 251478016 28742 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754816 140027798845003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 61396 28742 9700 1052 0 37391 0
[pid=23345/tid=23350] ppid=23344 vsize=245584 CPUtime=3.15
/proc/23345/task/23350/stat : 23350 (aptitude) R 23344 23345 17863 34816 17863 4202560 12684 2207 0 0 311 3 1 0 20 0 2 0 28930553 251478016 28742 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720918552 140027832710113 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) 245584

[startup+12.7003 s]
/proc/loadavg: 1.05 1.07 1.01 2/57 23351
/proc/meminfo: memFree=760472/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=280828 CPUtime=12.63
/proc/23345/stat : 23345 (aptitude) S 23344 23345 17863 34816 17863 4202496 42195 2207 0 0 1241 21 1 0 20 0 2 0 28930487 287567872 37533 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754816 140027798845003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 70207 37533 9700 1052 0 46202 0
[pid=23345/tid=23350] ppid=23344 vsize=280828 CPUtime=9.52
/proc/23345/task/23350/stat : 23350 (aptitude) R 23344 23345 17863 34816 17863 4202560 21574 2207 0 0 943 8 1 0 20 0 2 0 28930553 287567872 37533 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720918552 140027787600592 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) 280828

[startup+25.5003 s]
/proc/loadavg: 1.04 1.07 1.01 2/57 23351
/proc/meminfo: memFree=659412/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=380140 CPUtime=25.37
/proc/23345/stat : 23345 (aptitude) S 23344 23345 17863 34816 17863 4202496 67341 2207 0 0 2503 33 1 0 20 0 2 0 28930487 389263360 62308 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754816 140027798845003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 95035 62308 9700 1052 0 71030 0
[pid=23345/tid=23350] ppid=23344 vsize=380140 CPUtime=22.26
/proc/23345/task/23350/stat : 23350 (aptitude) R 23344 23345 17863 34816 17863 4202560 46720 2207 0 0 2205 20 1 0 20 0 2 0 28930553 389263360 62308 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720920664 140027830929072 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) 380140

[startup+51.1003 s]
/proc/loadavg: 1.08 1.08 1.01 2/57 23351
/proc/meminfo: memFree=491020/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=550200 CPUtime=50.86
/proc/23345/stat : 23345 (aptitude) S 23344 23345 17863 34816 17863 4202496 109847 2207 0 0 5029 56 1 0 20 0 2 0 28930487 563404800 104799 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754816 140027798845003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 137550 104799 9714 1052 0 113545 0
[pid=23345/tid=23350] ppid=23344 vsize=550200 CPUtime=47.74
/proc/23345/task/23350/stat : 23350 (aptitude) R 23344 23345 17863 34816 17863 4202560 89219 2207 0 0 4731 42 1 0 20 0 2 0 28930553 563404800 104799 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720918728 140027787600144 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.86
Current children cumulated vsize (KiB) 550200

[startup+102.3 s]
/proc/loadavg: 1.26 1.12 1.03 2/57 23575
/proc/meminfo: memFree=8044/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=987268 CPUtime=97.65
/proc/23345/stat : 23345 (aptitude) S 23344 23345 17863 34816 17863 4202496 219136 2207 9 0 9637 127 1 0 20 0 2 0 28930487 1010962432 213909 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754816 140027798845003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 246817 213909 9641 1052 0 222812 0
[pid=23345/tid=23350] ppid=23344 vsize=987268 CPUtime=94.52
/proc/23345/task/23350/stat : 23350 (aptitude) R 23344 23345 17863 34816 17863 4202560 198508 2207 9 0 9338 113 1 0 20 0 2 0 28930553 1010962432 213909 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720918600 140027832815337 0 134217728 4096 0 0 0 0 -1 0 0 0 139 0 0
Current children cumulated CPU time (s) 97.65
Current children cumulated vsize (KiB) 987268



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+120.4 s]
/proc/loadavg: 1.27 1.13 1.03 2/57 23575
/proc/meminfo: memFree=10112/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=1151416 CPUtime=113.94
/proc/23345/stat : 23345 (aptitude) S 23344 23345 17863 34816 17863 4202496 260276 2207 110 0 11233 160 1 0 20 0 2 0 28930487 1179049984 233861 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754816 140027798845003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 287854 233861 8520 1052 0 263849 0
[pid=23345/tid=23350] ppid=23344 vsize=1151416 CPUtime=110.82
/proc/23345/task/23350/stat : 23350 (aptitude) R 23344 23345 17863 34816 17863 4202560 239648 2207 110 0 10935 146 1 0 20 0 2 0 28930553 1179049984 233861 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720921480 140027832725835 0 134217728 4096 0 0 0 0 -1 0 0 0 252 0 0
Current children cumulated CPU time (s) 113.94
Current children cumulated vsize (KiB) 1151416

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

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

[startup+120.4 s]
/proc/loadavg: 1.27 1.13 1.03 2/57 23575
/proc/meminfo: memFree=10112/1022884 swapFree=0/0
[pid=23345] ppid=23344 vsize=1151416 CPUtime=113.94
/proc/23345/stat : 23345 (aptitude) S 23344 23345 17863 34816 17863 4202496 260276 2207 110 0 11233 160 1 0 20 0 2 0 28930487 1179049984 233861 18446744073709551615 140027830099968 140027834407320 140733307763056 140733307754816 140027798845003 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23345/statm: 287854 233861 8520 1052 0 263849 0
[pid=23345/tid=23350] ppid=23344 vsize=1151416 CPUtime=110.82
/proc/23345/task/23350/stat : 23350 (aptitude) R 23344 23345 17863 34816 17863 4202560 239648 2207 110 0 10935 146 1 0 20 0 2 0 28930553 1179049984 233861 18446744073709551615 140027830099968 140027834407320 140733307763056 140027720921480 140027832725835 0 134217728 4096 0 0 0 0 -1 0 0 0 252 0 0
Current children cumulated CPU time (s) 113.94
Current children cumulated vsize (KiB) 1151416

Child ended because it received signal 15 (SIGTERM)
Real time (s): 120.656
CPU time (s): 114.155
CPU user time (s): 112.475
CPU system time (s): 1.6801
CPU usage (%): 94.6119
Max. virtual memory (cumulated for all children) (KiB): 1151416

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 112.475
system time used= 1.6801
maximum resident set size= 939116
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262764
page faults= 111
swaps= 0
block input operations= 5944
block output operations= 72
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 449
involuntary context switches= 6937

runsolver used 0.204012 second user time and 0.360022 second system time

The end