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/26.runsolver.aptitude aptitude -s -y --without-recommends install libproc-daemon-perl ipmasqadm zbdesk evms-gui xgmod 

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.05 1.07 1.02 2/55 23127
/proc/meminfo: memFree=864444/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=3152 CPUtime=0
/proc/23127/stat : 23127 (runsolver) R 23126 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28831134 3227648 33 18446744073709551615 134512640 134586868 4290249280 4290247328 4151800880 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.112552 s]
/proc/loadavg: 1.05 1.07 1.02 2/55 23127
/proc/meminfo: memFree=864444/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=100508 CPUtime=0.09
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 10529 1708 0 0 6 3 0 0 20 0 1 0 28831134 102920192 10331 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649056 140133052491435 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 25127 10331 9156 1052 0 1122 0
Current children cumulated CPU time (s) 0.09
Current children cumulated vsize (KiB) 100508

[startup+0.200301 s]
/proc/loadavg: 1.05 1.07 1.02 2/55 23127
/proc/meminfo: memFree=864444/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=100508 CPUtime=0.18
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 10605 1708 0 0 15 3 0 0 20 0 1 0 28831134 102920192 10407 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649056 140133052498595 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23127/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.05 1.07 1.02 2/55 23127
/proc/meminfo: memFree=864444/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=111108 CPUtime=0.28
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 13340 1708 0 0 24 4 0 0 20 0 1 0 28831134 113774592 13134 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649440 140133052404173 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 27777 13134 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700196 s]
/proc/loadavg: 1.05 1.07 1.02 2/55 23127
/proc/meminfo: memFree=864444/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=123288 CPUtime=0.68
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 17027 1708 0 0 61 7 0 0 20 0 2 0 28831134 126246912 14303 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357653576 140133052336912 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50023 s]
/proc/loadavg: 1.05 1.07 1.02 2/57 23132
/proc/meminfo: memFree=836164/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=132384 CPUtime=1.48
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 19434 1708 0 0 140 8 0 0 20 0 2 0 28831134 135561216 16705 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357648144 140133060650758 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 33096 16705 9585 1052 0 9091 0
[pid=23127/tid=23132] ppid=23126 vsize=132384 CPUtime=0
/proc/23127/task/23132/stat : 23132 (aptitude) S 23126 23127 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 28831197 135561216 16705 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948482048 140133026398932 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) 132384

[startup+3.10024 s]
/proc/loadavg: 1.05 1.07 1.02 2/57 23133
/proc/meminfo: memFree=835040/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=133792 CPUtime=3.08
/proc/23127/stat : 23127 (aptitude) S 23126 23127 17863 34816 17863 4202496 20745 2207 0 0 295 12 1 0 20 0 2 0 28831134 137003008 17063 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649552 140133026399819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 33448 17063 9694 1052 0 9443 0
[pid=23127/tid=23132] ppid=23126 vsize=133792 CPUtime=0.01
/proc/23127/task/23132/stat : 23132 (aptitude) R 23126 23127 17863 34816 17863 4202560 162 2207 0 0 0 0 1 0 20 0 2 0 28831197 137003008 17063 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948481928 140133060444155 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) 133792

[startup+6.30024 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=798592/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=245016 CPUtime=6.27
/proc/23127/stat : 23127 (aptitude) S 23126 23127 17863 34816 17863 4202496 32766 2207 0 0 608 18 1 0 20 0 2 0 28831134 250896384 28595 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649552 140133026399819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 61254 28595 9700 1052 0 37249 0
[pid=23127/tid=23132] ppid=23126 vsize=245016 CPUtime=3.2
/proc/23127/task/23132/stat : 23132 (aptitude) R 23126 23127 17863 34816 17863 4202560 12181 2207 0 0 313 6 1 0 20 0 2 0 28831197 250896384 28595 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948475576 140133060301450 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 245016

[startup+12.7002 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=753208/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=283372 CPUtime=12.63
/proc/23127/stat : 23127 (aptitude) S 23126 23127 17863 34816 17863 4202496 42671 2207 0 0 1240 22 1 0 20 0 2 0 28831134 290172928 38162 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649552 140133026399819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 70843 38162 9700 1052 0 46838 0
[pid=23127/tid=23132] ppid=23126 vsize=283372 CPUtime=9.56
/proc/23127/task/23132/stat : 23132 (aptitude) R 23126 23127 17863 34816 17863 4202560 22086 2207 0 0 945 10 1 0 20 0 2 0 28831197 290172928 38162 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948473496 140133015154997 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) 283372

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

[startup+12.8003 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=753208/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=284032 CPUtime=12.73
/proc/23127/stat : 23127 (aptitude) S 23126 23127 17863 34816 17863 4202496 42840 2207 0 0 1250 22 1 0 20 0 2 0 28831134 290848768 38331 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649552 140133026399819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 71008 38331 9700 1052 0 47003 0
[pid=23127/tid=23132] ppid=23126 vsize=284032 CPUtime=9.66
/proc/23127/task/23132/stat : 23132 (aptitude) R 23126 23127 17863 34816 17863 4202560 22255 2207 0 0 955 10 1 0 20 0 2 0 28831197 290848768 38331 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948473368 140133023969257 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.73
Current children cumulated vsize (KiB) 284032

[startup+16.0002 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=735104/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=301712 CPUtime=15.91
/proc/23127/stat : 23127 (aptitude) S 23126 23127 17863 34816 17863 4202496 47305 2207 0 0 1568 22 1 0 20 0 2 0 28831134 308953088 42753 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649552 140133026399819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 75428 42753 9700 1052 0 51423 0
[pid=23127/tid=23132] ppid=23126 vsize=301712 CPUtime=12.85
/proc/23127/task/23132/stat : 23132 (aptitude) R 23126 23127 17863 34816 17863 4202560 26720 2207 0 0 1274 10 1 0 20 0 2 0 28831197 308953088 42753 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948473416 140133059865690 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 15.91
Current children cumulated vsize (KiB) 301712

[startup+17.6002 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=718736/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=314016 CPUtime=17.51
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 50595 2207 0 0 1726 24 1 0 20 0 2 0 28831134 321552384 45964 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357647928 140133015150476 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 78504 45964 9748 1052 0 54492 0
[pid=23127/tid=23132] ppid=23126 vsize=314016 CPUtime=14.37
/proc/23127/task/23132/stat : 23132 (aptitude) S 23126 23127 17863 34816 17863 4202560 29793 2207 0 0 1424 12 1 0 20 0 2 0 28831197 321552384 45964 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948482048 140133026398932 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.51
Current children cumulated vsize (KiB) 314016

[startup+18.0002 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=718736/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=314068 CPUtime=17.91
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 53067 2207 0 0 1765 25 1 0 20 0 2 0 28831134 321605632 45983 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649992 140133059861839 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 78517 45983 9749 1052 0 54505 0
[pid=23127/tid=23132] ppid=23126 vsize=314068 CPUtime=14.37
/proc/23127/task/23132/stat : 23132 (aptitude) S 23126 23127 17863 34816 17863 4202560 29793 2207 0 0 1424 12 1 0 20 0 2 0 28831197 321605632 45983 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948482048 140133026398932 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 17.91
Current children cumulated vsize (KiB) 314068

[startup+18.2002 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=718736/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=314068 CPUtime=18.11
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 53224 2706 0 0 1781 28 1 1 20 0 2 0 28831134 321605632 46051 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357647880 140133015150699 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 78517 46051 9749 1052 0 54505 0
[pid=23127/tid=23132] ppid=23126 vsize=314068 CPUtime=14.38
/proc/23127/task/23132/stat : 23132 (aptitude) S 23126 23127 17863 34816 17863 4202560 29793 2706 0 0 1424 12 1 1 20 0 2 0 28831197 321605632 46051 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948482048 140133026398932 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.11
Current children cumulated vsize (KiB) 314068

[startup+18.3002 s]
/proc/loadavg: 1.04 1.07 1.02 2/57 23133
/proc/meminfo: memFree=718736/1022884 swapFree=0/0
[pid=23127] ppid=23126 vsize=314068 CPUtime=18.21
/proc/23127/stat : 23127 (aptitude) R 23126 23127 17863 34816 17863 4202496 53438 2706 0 0 1787 32 1 1 20 0 2 0 28831134 321605632 46176 18446744073709551615 140133057654784 140133061962136 140734357657792 140734357649768 140133015498821 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23127/statm: 78517 46176 9749 1052 0 54505 0
[pid=23127/tid=23132] ppid=23126 vsize=314068 CPUtime=14.38
/proc/23127/task/23132/stat : 23132 (aptitude) S 23126 23127 17863 34816 17863 4202560 29793 2706 0 0 1424 12 1 1 20 0 2 0 28831197 321605632 46176 18446744073709551615 140133057654784 140133061962136 140734357657792 140132948482048 140133026398932 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 18.21
Current children cumulated vsize (KiB) 314068

Child status: 0
Real time (s): 18.3766
CPU time (s): 18.2971
CPU user time (s): 17.9131
CPU system time (s): 0.384024
CPU usage (%): 99.5679
Max. virtual memory (cumulated for all children) (KiB): 314068

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 17.9131
system time used= 0.384024
maximum resident set size= 184704
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 56665
page faults= 0
swaps= 0
block input operations= 0
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 90
involuntary context switches= 368

runsolver used 0 second user time and 0.088005 second system time

The end