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-sid/logs/20.runsolver.aptitude aptitude -s -y --without-recommends install distcc geki2 qtstalker-doc rsh-client devscripts-el 

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.08 1.09 1.03 2/55 25149
/proc/meminfo: memFree=832992/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=3152 CPUtime=0
/proc/25149/stat : 25149 (runsolver) R 25148 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29355591 3227648 33 18446744073709551615 134512640 134586868 4287137152 4287135200 4151817264 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.168172 s]
/proc/loadavg: 1.08 1.09 1.03 2/55 25149
/proc/meminfo: memFree=832992/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=103288 CPUtime=0.15
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 11286 1710 0 0 12 3 0 0 20 0 1 0 29355591 105766912 11087 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844464 139838168483732 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 25822 11087 9875 1052 0 1159 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 103288

[startup+0.200276 s]
/proc/loadavg: 1.08 1.09 1.03 2/55 25149
/proc/meminfo: memFree=832992/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=103288 CPUtime=0.18
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 11298 1710 0 0 15 3 0 0 20 0 1 0 29355591 105766912 11099 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844464 139838131179060 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 25822 11099 9887 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300325 s]
/proc/loadavg: 1.08 1.09 1.03 2/55 25149
/proc/meminfo: memFree=832992/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=103432 CPUtime=0.28
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 11427 1710 0 0 25 3 0 0 20 0 1 0 29355591 105914368 11220 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466842976 139838168492025 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700204 s]
/proc/loadavg: 1.08 1.09 1.03 2/55 25149
/proc/meminfo: memFree=832992/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=123068 CPUtime=0.68
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 17688 1710 0 0 62 6 0 0 20 0 1 0 29355591 126021632 15965 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466842632 139838130825447 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50031 s]
/proc/loadavg: 1.08 1.09 1.03 2/57 25154
/proc/meminfo: memFree=813020/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=136056 CPUtime=1.48
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 20643 1710 0 0 140 8 0 0 20 0 2 0 29355591 139321344 17561 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844472 139838175840621 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 34014 17561 10207 1052 0 9351 0
[pid=25149/tid=25154] ppid=25148 vsize=136056 CPUtime=0
/proc/25149/task/25154/stat : 25154 (aptitude) S 25148 25149 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29355667 139321344 17561 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061316096 139838142382804 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) 136056

[startup+3.10031 s]
/proc/loadavg: 1.08 1.09 1.03 2/57 25154
/proc/meminfo: memFree=802728/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=137812 CPUtime=3.07
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 21989 2209 0 0 293 14 0 0 20 0 2 0 29355591 141119488 17934 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466839904 139838176346494 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 34453 17934 10303 1052 0 9790 0
[pid=25149/tid=25154] ppid=25148 vsize=137812 CPUtime=0
/proc/25149/task/25154/stat : 25154 (aptitude) S 25148 25149 17863 34816 17863 4202560 6 2209 0 0 0 0 0 0 20 0 2 0 29355667 141119488 17934 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061316096 139838142382804 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 137812

[startup+6.30031 s]
/proc/loadavg: 1.07 1.09 1.03 2/57 25155
/proc/meminfo: memFree=760692/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=251576 CPUtime=6.25
/proc/25149/stat : 25149 (aptitude) S 25148 25149 17863 34816 17863 4202496 34844 2209 0 0 604 21 0 0 20 0 2 0 29355591 257613824 30237 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844960 139838142383691 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 62894 30237 10359 1052 0 38231 0
[pid=25149/tid=25154] ppid=25148 vsize=251576 CPUtime=2.86
/proc/25149/task/25154/stat : 25154 (aptitude) R 25148 25149 17863 34816 17863 4202560 12855 2209 0 0 279 7 0 0 20 0 2 0 29355667 257613824 30237 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061309624 139838176240928 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 251576

[startup+12.7003 s]
/proc/loadavg: 1.07 1.09 1.03 2/57 25155
/proc/meminfo: memFree=712580/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=297468 CPUtime=12.62
/proc/25149/stat : 25149 (aptitude) S 25148 25149 17863 34816 17863 4202496 46652 2209 0 0 1234 28 0 0 20 0 2 0 29355591 304607232 41667 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844960 139838142383691 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 74367 41667 10360 1052 0 49704 0
[pid=25149/tid=25154] ppid=25148 vsize=297468 CPUtime=9.23
/proc/25149/task/25154/stat : 25154 (aptitude) R 25148 25149 17863 34816 17863 4202560 24663 2209 0 0 909 14 0 0 20 0 2 0 29355667 304607232 41667 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061307416 139838175849562 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 297468

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

[startup+12.8004 s]
/proc/loadavg: 1.07 1.09 1.03 2/57 25155
/proc/meminfo: memFree=712580/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=297996 CPUtime=12.72
/proc/25149/stat : 25149 (aptitude) S 25148 25149 17863 34816 17863 4202496 46804 2209 0 0 1244 28 0 0 20 0 2 0 29355591 305147904 41819 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844960 139838142383691 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 74499 41819 10360 1052 0 49836 0
[pid=25149/tid=25154] ppid=25148 vsize=297996 CPUtime=9.33
/proc/25149/task/25154/stat : 25154 (aptitude) R 25148 25149 17863 34816 17863 4202560 24815 2209 0 0 919 14 0 0 20 0 2 0 29355667 305147904 41819 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061309672 139838175849562 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.72
Current children cumulated vsize (KiB) 297996

[startup+19.2003 s]
/proc/loadavg: 1.06 1.09 1.03 2/57 25155
/proc/meminfo: memFree=668560/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=338172 CPUtime=19.08
/proc/25149/stat : 25149 (aptitude) S 25148 25149 17863 34816 17863 4202496 56859 2209 0 0 1875 33 0 0 20 0 2 0 29355591 346288128 51852 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844960 139838142383691 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 84543 51852 10360 1052 0 59880 0
[pid=25149/tid=25154] ppid=25148 vsize=338172 CPUtime=15.69
/proc/25149/task/25154/stat : 25154 (aptitude) R 25148 25149 17863 34816 17863 4202560 34870 2209 0 0 1550 19 0 0 20 0 2 0 29355667 346288128 51852 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061307416 139838169038704 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.08
Current children cumulated vsize (KiB) 338172

[startup+22.4003 s]
/proc/loadavg: 1.06 1.08 1.03 2/57 25155
/proc/meminfo: memFree=651820/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=354332 CPUtime=22.27
/proc/25149/stat : 25149 (aptitude) S 25148 25149 17863 34816 17863 4202496 60930 2209 0 0 2192 35 0 0 20 0 2 0 29355591 362835968 55900 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466844960 139838142383691 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 88583 55900 10360 1052 0 63920 0
[pid=25149/tid=25154] ppid=25148 vsize=354332 CPUtime=18.87
/proc/25149/task/25154/stat : 25154 (aptitude) R 25148 25149 17863 34816 17863 4202560 38941 2209 0 0 1866 21 0 0 20 0 2 0 29355667 362835968 55900 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061310344 139838176314905 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.27
Current children cumulated vsize (KiB) 354332

[startup+23.2031 s]
/proc/loadavg: 1.06 1.08 1.03 2/57 25155
/proc/meminfo: memFree=647108/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=356604 CPUtime=23.06
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 61726 2209 0 0 2271 35 0 0 20 0 2 0 29355591 365162496 56642 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466843336 139838176240928 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 89151 56642 10408 1052 0 64481 0
[pid=25149/tid=25154] ppid=25148 vsize=356604 CPUtime=19.53
/proc/25149/task/25154/stat : 25154 (aptitude) S 25148 25149 17863 34816 17863 4202560 39526 2209 0 0 1932 21 0 0 20 0 2 0 29355667 365162496 56642 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061316096 139838142382804 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.06
Current children cumulated vsize (KiB) 356604

[startup+23.6003 s]
/proc/loadavg: 1.06 1.08 1.03 2/57 25155
/proc/meminfo: memFree=647108/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=356640 CPUtime=23.46
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 64278 2209 0 0 2310 36 0 0 20 0 2 0 29355591 365199360 56623 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466845400 139838175359892 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 89160 56623 10409 1052 0 64490 0
[pid=25149/tid=25154] ppid=25148 vsize=356640 CPUtime=19.53
/proc/25149/task/25154/stat : 25154 (aptitude) S 25148 25149 17863 34816 17863 4202560 39526 2209 0 0 1932 21 0 0 20 0 2 0 29355667 365199360 56623 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061316096 139838142382804 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.46
Current children cumulated vsize (KiB) 356640

[startup+24.0003 s]
/proc/loadavg: 1.06 1.08 1.03 2/57 25155
/proc/meminfo: memFree=647108/1022884 swapFree=0/0
[pid=25149] ppid=25148 vsize=356640 CPUtime=23.86
/proc/25149/stat : 25149 (aptitude) R 25148 25149 17863 34816 17863 4202496 64693 2710 0 0 2339 46 0 1 20 0 2 0 29355591 365199360 56614 18446744073709551615 139838173638656 139838177946008 140734466853200 140734466845016 139838131760367 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25149/statm: 89160 56614 10409 1052 0 64490 0
[pid=25149/tid=25154] ppid=25148 vsize=356640 CPUtime=19.54
/proc/25149/task/25154/stat : 25154 (aptitude) S 25148 25149 17863 34816 17863 4202560 39526 2710 0 0 1932 21 0 1 20 0 2 0 29355667 365199360 56614 18446744073709551615 139838173638656 139838177946008 140734466853200 139838061316096 139838142382804 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.86
Current children cumulated vsize (KiB) 356640

Child status: 0
Real time (s): 24.0628
CPU time (s): 23.9455
CPU user time (s): 23.4055
CPU system time (s): 0.540033
CPU usage (%): 99.5124
Max. virtual memory (cumulated for all children) (KiB): 356640

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.4055
system time used= 0.540033
maximum resident set size= 227464
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67940
page faults= 0
swaps= 0
block input operations= 0
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 101
involuntary context switches= 455

runsolver used 0.036002 second user time and 0.088005 second system time

The end