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/98.runsolver.aptitude aptitude -s -y --without-recommends install xabacus wmanx rwall amiga-fdisk-cross libganglia1-dev 

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.19 1.10 1.04 2/55 24249
/proc/meminfo: memFree=957108/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=3152 CPUtime=0
/proc/24249/stat : 24249 (runsolver) R 24248 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29194092 3227648 32 18446744073709551615 134512640 134586868 4290608400 4290606448 4152206384 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/24249/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.19112 s]
/proc/loadavg: 1.19 1.10 1.04 2/55 24249
/proc/meminfo: memFree=957108/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=14396 CPUtime=0
/proc/24249/stat : 24249 (aptitude) D 24248 24249 17863 34816 17863 4202496 134 0 5 0 0 0 0 0 20 0 1 0 29194092 14741504 55 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592727208 140273000223498 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/24249/statm: 3599 55 38 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 14396

[startup+0.200385 s]
/proc/loadavg: 1.19 1.10 1.04 2/55 24249
/proc/meminfo: memFree=957108/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=14396 CPUtime=0
/proc/24249/stat : 24249 (aptitude) D 24248 24249 17863 34816 17863 4202496 134 0 5 0 0 0 0 0 20 0 1 0 29194092 14741504 55 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592727208 140273000223498 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/24249/statm: 3599 55 38 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 14396

[startup+0.300379 s]
/proc/loadavg: 1.19 1.10 1.04 2/55 24249
/proc/meminfo: memFree=957108/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=36128 CPUtime=0
/proc/24249/stat : 24249 (aptitude) D 24248 24249 17863 34816 17863 4202496 169 0 13 0 0 0 0 0 20 0 1 0 29194092 36995072 92 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592726728 140273000224134 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/24249/statm: 9032 92 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.700195 s]
/proc/loadavg: 1.19 1.10 1.04 2/55 24249
/proc/meminfo: memFree=957108/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=100508 CPUtime=0.01
/proc/24249/stat : 24249 (aptitude) R 24248 24249 17863 34816 17863 4202496 2216 1706 29 4 0 1 0 0 20 0 1 0 29194092 102920192 2046 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592721704 140272959909261 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/24249/statm: 25127 2046 990 1052 0 1122 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 100508

[startup+1.50033 s]
/proc/loadavg: 1.19 1.10 1.04 1/56 24253
/proc/meminfo: memFree=949660/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=100508 CPUtime=0.02
/proc/24249/stat : 24249 (aptitude) D 24248 24249 17863 34816 17863 4202496 6166 1706 153 4 0 2 0 0 20 0 1 0 29194092 102920192 6118 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592721776 140272997414744 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/24249/statm: 25127 6118 4943 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+3.10021 s]
/proc/loadavg: 1.19 1.10 1.04 2/56 24253
/proc/meminfo: memFree=929324/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=123292 CPUtime=0.74
/proc/24249/stat : 24249 (aptitude) R 24248 24249 17863 34816 17863 4202496 16828 1706 202 4 59 15 0 0 20 0 2 0 29194092 126251008 14303 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592726088 140272997087693 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 230 0 0
/proc/24249/statm: 30823 14303 9482 1052 0 6818 0
Current children cumulated CPU time (s) 0.74
Current children cumulated vsize (KiB) 123292
heavy processes:

[startup+6.30023 s]
/proc/loadavg: 1.17 1.10 1.04 2/57 24255
/proc/meminfo: memFree=842392/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=149896 CPUtime=3.87
/proc/24249/stat : 24249 (aptitude) S 24248 24249 17863 34816 17863 4202496 24714 2202 202 5 366 21 0 0 20 0 2 0 29194092 153493504 21195 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592722064 140272971109963 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/24249/statm: 37474 21195 9700 1052 0 13469 0
[pid=24249/tid=24254] ppid=24248 vsize=149896 CPUtime=0.73
/proc/24249/task/24254/stat : 24254 (aptitude) R 24248 24249 17863 34816 17863 4202560 4339 2202 0 5 71 2 0 0 20 0 2 0 29194397 153493504 21195 18446744073709551615 140273002364928 140273006672280 140734592730304 140272893185720 140273005072614 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.87
Current children cumulated vsize (KiB) 149896
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.16 1.09 1.04 2/57 24255
/proc/meminfo: memFree=772580/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=273688 CPUtime=10.24
/proc/24249/stat : 24249 (aptitude) S 24248 24249 17863 34816 17863 4202496 40089 2202 202 5 998 26 0 0 20 0 2 0 29194092 280256512 35736 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592722064 140272971109963 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/24249/statm: 68422 35736 9700 1052 0 44417 0
[pid=24249/tid=24254] ppid=24248 vsize=273688 CPUtime=7.09
/proc/24249/task/24254/stat : 24254 (aptitude) R 24248 24249 17863 34816 17863 4202560 19713 2202 0 5 703 6 0 0 20 0 2 0 29194397 280256512 35736 18446744073709551615 140273002364928 140273006672280 140734592730304 140272893185720 140272959866672 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.24
Current children cumulated vsize (KiB) 273688

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

[startup+12.8003 s]
/proc/loadavg: 1.16 1.09 1.04 2/57 24255
/proc/meminfo: memFree=772580/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=274480 CPUtime=10.34
/proc/24249/stat : 24249 (aptitude) S 24248 24249 17863 34816 17863 4202496 40293 2202 202 5 1008 26 0 0 20 0 2 0 29194092 281067520 35940 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592722064 140272971109963 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/24249/statm: 68620 35940 9700 1052 0 44615 0
[pid=24249/tid=24254] ppid=24248 vsize=274480 CPUtime=7.19
/proc/24249/task/24254/stat : 24254 (aptitude) R 24248 24249 17863 34816 17863 4202560 19917 2202 0 5 713 6 0 0 20 0 2 0 29194397 281067520 35940 18446744073709551615 140273002364928 140273006672280 140734592730304 140272893185720 140273004961977 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.34
Current children cumulated vsize (KiB) 274480

[startup+13.6002 s]
/proc/loadavg: 1.14 1.09 1.04 1/57 24255
/proc/meminfo: memFree=762784/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=276648 CPUtime=11.04
/proc/24249/stat : 24249 (aptitude) R 24248 24249 17863 34816 17863 4202496 43486 2202 215 5 1077 27 0 0 20 0 2 0 29194092 283287552 36598 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592722504 140273004566354 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 240 0 0
/proc/24249/statm: 69162 36598 9749 1052 0 45150 0
[pid=24249/tid=24254] ppid=24248 vsize=276648 CPUtime=7.49
/proc/24249/task/24254/stat : 24254 (aptitude) S 24248 24249 17863 34816 17863 4202560 20447 2202 1 5 742 7 0 0 20 0 2 0 29194397 283287552 36598 18446744073709551615 140273002364928 140273006672280 140734592730304 140272893192192 140272971109076 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 11.04
Current children cumulated vsize (KiB) 276648

[startup+14.0003 s]
/proc/loadavg: 1.14 1.09 1.04 1/57 24255
/proc/meminfo: memFree=762784/1022884 swapFree=0/0
[pid=24249] ppid=24248 vsize=141864 CPUtime=11.36
/proc/24249/stat : 24249 (aptitude) D 24248 24249 17863 34816 17863 4202496 44358 2701 229 5 1096 39 0 1 20 0 1 0 29194092 145268736 2949 18446744073709551615 140273002364928 140273006672280 140734592730304 140734592729376 140272968524720 0 134217728 4096 0 0 0 0 17 0 0 0 247 0 0
/proc/24249/statm: 35466 2949 1527 1052 0 19722 0
Current children cumulated CPU time (s) 11.36
Current children cumulated vsize (KiB) 141864

Child status: 0
Real time (s): 14.0198
CPU time (s): 11.3887
CPU user time (s): 10.9767
CPU system time (s): 0.412025
CPU usage (%): 81.233
Max. virtual memory (cumulated for all children) (KiB): 276648

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.9767
system time used= 0.412025
maximum resident set size= 147340
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 47078
page faults= 237
swaps= 0
block input operations= 174560
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1807
involuntary context switches= 239

runsolver used 0.024001 second user time and 0.052003 second system time

The end