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/53.runsolver.aptitude aptitude -s -y --without-recommends install netsaint-statd-plugins libvncauth0 libt1-dev perl-base ipvsadm 

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.08 1.02 2/55 23605
/proc/meminfo: memFree=813140/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=3152 CPUtime=0
/proc/23605/stat : 23605 (runsolver) R 23604 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28953131 3227648 32 18446744073709551615 134512640 134586868 4288526400 4288524448 4151878704 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.110706 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23605
/proc/meminfo: memFree=813140/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=100508 CPUtime=0.1
/proc/23605/stat : 23605 (aptitude) R 23604 23605 17863 34816 17863 4202496 10493 1708 0 0 8 2 0 0 20 0 1 0 28953131 102920192 10293 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525021712 139647535715993 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 25127 10293 9118 1052 0 1122 0
Current children cumulated CPU time (s) 0.1
Current children cumulated vsize (KiB) 100508

[startup+0.200281 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23605
/proc/meminfo: memFree=813140/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=100508 CPUtime=0.18
/proc/23605/stat : 23605 (aptitude) R 23604 23605 17863 34816 17863 4202496 10607 1708 0 0 16 2 0 0 20 0 1 0 28953131 102920192 10407 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525021712 139647535716099 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300271 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23605
/proc/meminfo: memFree=813140/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=111108 CPUtime=0.28
/proc/23605/stat : 23605 (aptitude) R 23604 23605 17863 34816 17863 4202496 11739 1708 0 0 26 2 0 0 20 0 1 0 28953131 113774592 11531 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525022040 139647543006828 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 27777 11531 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700204 s]
/proc/loadavg: 1.03 1.08 1.02 2/55 23605
/proc/meminfo: memFree=813140/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=123288 CPUtime=0.69
/proc/23605/stat : 23605 (aptitude) R 23604 23605 17863 34816 17863 4202496 17029 1708 0 0 63 6 0 0 20 0 2 0 28953131 126246912 14303 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525026232 139647499027648 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23610
/proc/meminfo: memFree=789696/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=132452 CPUtime=1.48
/proc/23605/stat : 23605 (aptitude) R 23604 23605 17863 34816 17863 4202496 19449 1708 0 0 142 6 0 0 20 0 2 0 28953131 135630848 16719 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525020800 139647542503762 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 33113 16719 9585 1052 0 9108 0
[pid=23605/tid=23610] ppid=23604 vsize=132452 CPUtime=0
/proc/23605/task/23610/stat : 23610 (aptitude) S 23604 23605 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 28953196 135630848 16719 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431702528 139647509619412 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) 132452

[startup+3.10024 s]
/proc/loadavg: 1.03 1.08 1.02 2/57 23611
/proc/meminfo: memFree=783736/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=133860 CPUtime=3.08
/proc/23605/stat : 23605 (aptitude) R 23604 23605 17863 34816 17863 4202496 20647 2211 0 0 297 10 0 1 20 0 2 0 28953131 137072640 16966 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525017152 139647544300996 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 33465 16966 9644 1052 0 9460 0
[pid=23605/tid=23610] ppid=23604 vsize=133860 CPUtime=0.01
/proc/23605/task/23610/stat : 23610 (aptitude) S 23604 23605 17863 34816 17863 4202560 6 2211 0 0 0 0 0 1 20 0 2 0 28953196 137072640 16966 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431702528 139647509619412 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) 133860

[startup+6.30025 s]
/proc/loadavg: 1.02 1.08 1.02 2/57 23611
/proc/meminfo: memFree=740592/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=245868 CPUtime=6.26
/proc/23605/stat : 23605 (aptitude) S 23604 23605 17863 34816 17863 4202496 33210 2211 0 0 610 15 0 1 20 0 2 0 28953131 251768832 28787 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525022208 139647509620299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 61467 28787 9700 1052 0 37462 0
[pid=23605/tid=23610] ppid=23604 vsize=245868 CPUtime=3.14
/proc/23605/task/23610/stat : 23610 (aptitude) R 23604 23605 17863 34816 17863 4202560 12562 2211 0 0 308 5 0 1 20 0 2 0 28953196 251768832 28787 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431693848 139647543677239 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) 245868

[startup+12.7003 s]
/proc/loadavg: 1.02 1.07 1.02 2/57 23611
/proc/meminfo: memFree=692604/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=293844 CPUtime=12.64
/proc/23605/stat : 23605 (aptitude) S 23604 23605 17863 34816 17863 4202496 45752 2211 0 0 1241 22 0 1 20 0 2 0 28953131 300896256 40789 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525022208 139647509620299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 73461 40789 9700 1052 0 49456 0
[pid=23605/tid=23610] ppid=23604 vsize=293844 CPUtime=9.51
/proc/23605/task/23610/stat : 23610 (aptitude) R 23604 23605 17863 34816 17863 4202560 25104 2211 0 0 938 12 0 1 20 0 2 0 28953196 300896256 40789 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431693848 139647543677929 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 293844

[startup+25.5003 s]
/proc/loadavg: 1.02 1.07 1.01 2/57 23611
/proc/meminfo: memFree=590552/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=395104 CPUtime=25.37
/proc/23605/stat : 23605 (aptitude) S 23604 23605 17863 34816 17863 4202496 71124 2211 0 0 2504 32 0 1 20 0 2 0 28953131 404586496 66086 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525022208 139647509620299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 98776 66086 9700 1052 0 74771 0
[pid=23605/tid=23610] ppid=23604 vsize=395104 CPUtime=22.25
/proc/23605/task/23610/stat : 23610 (aptitude) R 23604 23605 17863 34816 17863 4202560 50476 2211 0 0 2202 22 0 1 20 0 2 0 28953196 404586496 66086 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431696056 139647498366568 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) 395104

[startup+51.1003 s]
/proc/loadavg: 1.01 1.06 1.01 2/57 23611
/proc/meminfo: memFree=375660/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=611848 CPUtime=50.86
/proc/23605/stat : 23605 (aptitude) S 23604 23605 17863 34816 17863 4202496 125343 2211 0 0 5028 57 0 1 20 0 2 0 28953131 626532352 120223 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525022208 139647509620299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 152962 120223 9716 1052 0 128957 0
[pid=23605/tid=23610] ppid=23604 vsize=611848 CPUtime=47.73
/proc/23605/task/23610/stat : 23610 (aptitude) R 23604 23605 17863 34816 17863 4202560 104689 2211 0 0 4725 47 0 1 20 0 2 0 28953196 626532352 120223 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431693848 139647543086170 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) 611848



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+100 s]
/proc/loadavg: 1.22 1.10 1.02 2/57 23611
/proc/meminfo: memFree=9384/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=1152420 CPUtime=96.46
/proc/23605/stat : 23605 (aptitude) S 23604 23605 17863 34816 17863 4202496 260779 2211 333 0 9512 133 0 1 20 0 2 0 28953131 1180078080 247492 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525022208 139647509620299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 288105 247492 8618 1052 0 264100 0
[pid=23605/tid=23610] ppid=23604 vsize=1152420 CPUtime=93.33
/proc/23605/task/23610/stat : 23610 (aptitude) R 23604 23605 17863 34816 17863 4202560 240125 2211 333 0 9209 123 0 1 20 0 2 0 28953196 1180078080 247492 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431693848 139647498741226 0 134217728 4096 0 0 0 0 -1 0 0 0 269 0 0
Current children cumulated CPU time (s) 96.46
Current children cumulated vsize (KiB) 1152420

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

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

[startup+100 s]
/proc/loadavg: 1.22 1.10 1.02 2/57 23611
/proc/meminfo: memFree=9384/1022884 swapFree=0/0
[pid=23605] ppid=23604 vsize=1152420 CPUtime=96.46
/proc/23605/stat : 23605 (aptitude) S 23604 23605 17863 34816 17863 4202496 260779 2211 333 0 9512 133 0 1 20 0 2 0 28953131 1180078080 247492 18446744073709551615 139647540875264 139647545182616 140733525030448 140733525022208 139647509620299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23605/statm: 288105 247492 8618 1052 0 264100 0
[pid=23605/tid=23610] ppid=23604 vsize=1152420 CPUtime=93.33
/proc/23605/task/23610/stat : 23610 (aptitude) R 23604 23605 17863 34816 17863 4202560 240125 2211 333 0 9209 123 0 1 20 0 2 0 28953196 1180078080 247492 18446744073709551615 139647540875264 139647545182616 140733525030448 139647431693848 139647498741226 0 134217728 4096 0 0 0 0 -1 0 0 0 269 0 0
Current children cumulated CPU time (s) 96.46
Current children cumulated vsize (KiB) 1152420

Child ended because it received signal 15 (SIGTERM)
Real time (s): 100.126
CPU time (s): 96.582
CPU user time (s): 95.1659
CPU system time (s): 1.41609
CPU usage (%): 96.4602
Max. virtual memory (cumulated for all children) (KiB): 1152420

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 95.1659
system time used= 1.41609
maximum resident set size= 991996
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263073
page faults= 333
swaps= 0
block input operations= 8000
block output operations= 64
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 631
involuntary context switches= 2364

runsolver used 0.144009 second user time and 0.32002 second system time

The end