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/69.runsolver.aptitude aptitude -s -y --without-recommends install libforms-dev libdbd-mysql-ruby libxmp2 libinline-octave-perl libgnomeada2-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.07 1.07 1.01 2/55 23756
/proc/meminfo: memFree=962860/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=3152 CPUtime=0
/proc/23756/stat : 23756 (runsolver) R 23755 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29021795 3227648 33 18446744073709551615 134512640 134586868 4288696896 4288694944 4151837744 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23756/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.18725 s]
/proc/loadavg: 1.07 1.07 1.01 2/55 23756
/proc/meminfo: memFree=962860/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=28716 CPUtime=0
/proc/23756/stat : 23756 (aptitude) D 23755 23756 17863 34816 17863 4202496 155 0 11 0 0 0 0 0 20 0 1 0 29021795 29405184 78 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008466488 140228375500323 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/23756/statm: 7179 78 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.200277 s]
/proc/loadavg: 1.07 1.07 1.01 2/55 23756
/proc/meminfo: memFree=962860/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=33024 CPUtime=0
/proc/23756/stat : 23756 (aptitude) D 23755 23756 17863 34816 17863 4202496 162 0 13 0 0 0 0 0 20 0 1 0 29021795 33816576 86 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008466296 140228375500323 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23756/statm: 8256 86 55 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 33024

[startup+0.300319 s]
/proc/loadavg: 1.07 1.07 1.01 2/55 23756
/proc/meminfo: memFree=962860/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=54972 CPUtime=0
/proc/23756/stat : 23756 (aptitude) D 23755 23756 17863 34816 17863 4202496 995 0 25 0 0 0 0 0 20 0 1 0 29021795 56291328 912 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008466392 140228335486704 0 134217728 0 0 0 0 0 17 0 0 0 28 0 0
/proc/23756/statm: 13743 912 760 1052 0 107 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54972

[startup+0.70025 s]
/proc/loadavg: 1.07 1.07 1.01 2/55 23756
/proc/meminfo: memFree=962860/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=100508 CPUtime=0.02
/proc/23756/stat : 23756 (aptitude) D 23755 23756 17863 34816 17863 4202496 3006 1705 61 4 1 1 0 0 20 0 1 0 29021795 102920192 2868 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461344 140228372690842 0 134217728 4096 0 0 0 0 17 0 0 0 64 0 0
/proc/23756/statm: 25127 2868 1693 1052 0 1122 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 100508

[startup+1.50021 s]
/proc/loadavg: 1.07 1.07 1.01 1/56 23760
/proc/meminfo: memFree=955032/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=100508 CPUtime=0.05
/proc/23756/stat : 23756 (aptitude) R 23755 23756 17863 34816 17863 4202496 7658 1705 196 4 3 2 0 0 20 0 1 0 29021795 102920192 7655 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461136 140228372363792 0 134217728 4096 0 0 0 0 17 0 0 0 140 0 0
/proc/23756/statm: 25127 7655 6480 1052 0 1122 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 100508

[startup+3.10025 s]
/proc/loadavg: 1.07 1.07 1.01 2/56 23760
/proc/meminfo: memFree=922420/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=123292 CPUtime=0.81
/proc/23756/stat : 23756 (aptitude) R 23755 23756 17863 34816 17863 4202496 16795 1705 233 4 66 15 0 0 20 0 2 0 29021795 126251008 14303 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008465656 140228372465187 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 225 0 0
/proc/23756/statm: 30823 14303 9482 1052 0 6818 0
Current children cumulated CPU time (s) 0.81
Current children cumulated vsize (KiB) 123292
heavy processes:

[startup+6.30025 s]
/proc/loadavg: 1.07 1.07 1.01 2/57 23762
/proc/meminfo: memFree=841440/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=149808 CPUtime=3.91
/proc/23756/stat : 23756 (aptitude) S 23755 23756 17863 34816 17863 4202496 24673 2202 233 6 369 22 0 0 20 0 2 0 29021795 153403392 21159 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461632 140228346385995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 226 0 0
/proc/23756/statm: 37452 21159 9700 1052 0 13447 0
[pid=23756/tid=23761] ppid=23755 vsize=149808 CPUtime=0.74
/proc/23756/task/23761/stat : 23761 (aptitude) R 23755 23756 17863 34816 17863 4202560 4307 2202 0 6 73 1 0 0 20 0 2 0 29022092 153403392 21159 18446744073709551615 140228377640960 140228381948312 140737008469872 140228268459112 140228380316716 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.91
Current children cumulated vsize (KiB) 149808
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.06 1.07 1.01 2/57 23762
/proc/meminfo: memFree=764312/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=280056 CPUtime=10.27
/proc/23756/stat : 23756 (aptitude) S 23755 23756 17863 34816 17863 4202496 41621 2202 233 6 999 28 0 0 20 0 2 0 29021795 286777344 37335 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461632 140228346385995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 226 0 0
/proc/23756/statm: 70014 37335 9700 1052 0 46009 0
[pid=23756/tid=23761] ppid=23755 vsize=280056 CPUtime=7.11
/proc/23756/task/23761/stat : 23761 (aptitude) R 23755 23756 17863 34816 17863 4202560 21254 2202 0 6 703 8 0 0 20 0 2 0 29022092 286777344 37335 18446744073709551615 140228377640960 140228381948312 140737008469872 140228268459544 140228379851869 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.27
Current children cumulated vsize (KiB) 280056

[startup+25.5003 s]
/proc/loadavg: 1.05 1.06 1.01 2/57 23762
/proc/meminfo: memFree=658416/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=383020 CPUtime=23.01
/proc/23756/stat : 23756 (aptitude) S 23755 23756 17863 34816 17863 4202496 67829 2202 233 6 2261 40 0 0 20 0 2 0 29021795 392212480 63040 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461632 140228346385995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 226 0 0
/proc/23756/statm: 95755 63040 9701 1052 0 71750 0
[pid=23756/tid=23761] ppid=23755 vsize=383020 CPUtime=19.85
/proc/23756/task/23761/stat : 23761 (aptitude) R 23755 23756 17863 34816 17863 4202560 47462 2202 0 6 1965 20 0 0 20 0 2 0 29022092 392212480 63040 18446744073709551615 140228377640960 140228381948312 140737008469872 140228268459496 140228335151200 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.01
Current children cumulated vsize (KiB) 383020

[startup+51.1003 s]
/proc/loadavg: 1.03 1.06 1.00 2/57 23762
/proc/meminfo: memFree=491016/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=550928 CPUtime=48.5
/proc/23756/stat : 23756 (aptitude) S 23755 23756 17863 34816 17863 4202496 109807 2202 233 6 4794 56 0 0 20 0 2 0 29021795 564150272 105000 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461632 140228346385995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 226 0 0
/proc/23756/statm: 137732 105000 9715 1052 0 113727 0
[pid=23756/tid=23761] ppid=23755 vsize=550928 CPUtime=45.33
/proc/23756/task/23761/stat : 23761 (aptitude) R 23755 23756 17863 34816 17863 4202560 89434 2202 0 6 4497 36 0 0 20 0 2 0 29022092 564150272 105000 18446744073709551615 140228377640960 140228381948312 140737008469872 140228268459720 140228380400884 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 48.5
Current children cumulated vsize (KiB) 550928

[startup+102.3 s]
/proc/loadavg: 1.07 1.06 1.00 2/57 23762
/proc/meminfo: memFree=18452/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=1020336 CPUtime=99.46
/proc/23756/stat : 23756 (aptitude) S 23755 23756 17863 34816 17863 4202496 227183 2202 233 6 9836 110 0 0 20 0 2 0 29021795 1044824064 222298 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461632 140228346385995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 226 0 0
/proc/23756/statm: 255084 222298 9716 1052 0 231079 0
[pid=23756/tid=23761] ppid=23755 vsize=1020336 CPUtime=96.29
/proc/23756/task/23761/stat : 23761 (aptitude) R 23755 23756 17863 34816 17863 4202560 206810 2202 0 6 9539 90 0 0 20 0 2 0 29022092 1044824064 222298 18446744073709551615 140228377640960 140228381948312 140737008469872 140228268461704 140228378286386 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 99.46
Current children cumulated vsize (KiB) 1020336



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+124.8 s]
/proc/loadavg: 1.38 1.13 1.03 2/57 23762
/proc/meminfo: memFree=9508/1022884 swapFree=0/0
[pid=23756] ppid=23755 vsize=1151460 CPUtime=119.62
/proc/23756/stat : 23756 (aptitude) S 23755 23756 17863 34816 17863 4202496 260065 2202 452 6 11829 133 0 0 20 0 2 0 29021795 1179095040 243189 18446744073709551615 140228377640960 140228381948312 140737008469872 140737008461632 140228346385995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 226 0 0
/proc/23756/statm: 287865 243189 9626 1052 0 263860 0
[pid=23756/tid=23761] ppid=23755 vsize=1151460 CPUtime=116.45
/proc/23756/task/23761/stat : 23761 (aptitude) R 23755 23756 17863 34816 17863 4202560 239680 2202 215 6 11532 113 0 0 20 0 2 0 29022092 1179095040 243189 18446744073709551615 140228377640960 140228381948312 140737008469872 140228268460040 140228335222464 0 134217728 4096 0 0 0 0 -1 0 0 0 186 0 0
Current children cumulated CPU time (s) 119.62
Current children cumulated vsize (KiB) 1151460

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

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

Child ended because it received signal 15 (SIGTERM)
Real time (s): 124.9
CPU time (s): 119.735
CPU user time (s): 118.323
CPU system time (s): 1.41209
CPU usage (%): 95.8653
Max. virtual memory (cumulated for all children) (KiB): 1151460

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 118.323
system time used= 1.41209
maximum resident set size= 979780
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262267
page faults= 458
swaps= 0
block input operations= 196864
block output operations= 80
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2266
involuntary context switches= 2936

runsolver used 0.204012 second user time and 0.392024 second system time

The end