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/logs/71.runsolver.aptitude aptitude -s -y --without-recommends install spread libffcall1 mirror gcompris cvstrac 

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.07 0.99 2/55 21704
/proc/meminfo: memFree=912672/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=3152 CPUtime=0
/proc/21704/stat : 21704 (runsolver) R 21703 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28543150 3227648 32 18446744073709551615 134512640 134586868 4289150064 4289148112 4151845936 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.135576 s]
/proc/loadavg: 1.19 1.07 0.99 2/55 21704
/proc/meminfo: memFree=912672/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=89152 CPUtime=0.12
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 7770 1707 0 0 10 2 0 0 20 0 1 0 28543150 91291648 7570 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712192 140198500453949 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 22288 7570 6660 1052 0 858 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 89152

[startup+0.200297 s]
/proc/loadavg: 1.19 1.07 0.99 2/55 21704
/proc/meminfo: memFree=912672/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=89152 CPUtime=0.19
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 7869 1707 0 0 17 2 0 0 20 0 1 0 28543150 91291648 7661 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214710704 140198499907554 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 22288 7661 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300288 s]
/proc/loadavg: 1.19 1.07 0.99 2/55 21704
/proc/meminfo: memFree=912672/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=101864 CPUtime=0.29
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 11583 1707 0 0 26 3 0 0 20 0 1 0 28543150 104308736 10630 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214710296 140198507979365 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 25466 10630 6742 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700206 s]
/proc/loadavg: 1.19 1.07 0.99 2/55 21704
/proc/meminfo: memFree=912672/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=110228 CPUtime=0.68
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 12635 1707 0 0 63 5 0 0 20 0 2 0 28543150 112873472 11008 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712968 140198507761894 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 27557 11008 6961 1052 0 6127 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 110228

[startup+1.50026 s]
/proc/loadavg: 1.19 1.07 0.99 2/57 21709
/proc/meminfo: memFree=891832/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=115472 CPUtime=1.48
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 14564 2205 0 0 138 9 1 0 20 0 2 0 28543150 118243328 12360 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712952 140198471366944 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 28868 12360 7073 1052 0 7438 0
[pid=21704/tid=21709] ppid=21703 vsize=115472 CPUtime=0.01
/proc/21704/task/21709/stat : 21709 (aptitude) S 21703 21704 17863 34816 17863 4202560 6 2205 0 0 0 0 1 0 20 0 2 0 28543195 118243328 12360 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408460288 140198473798356 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) 115472

[startup+3.10024 s]
/proc/loadavg: 1.17 1.07 0.99 2/57 21710
/proc/meminfo: memFree=885012/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=202132 CPUtime=3.08
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 20841 2205 0 0 296 11 1 0 20 0 2 0 28543150 206983168 17869 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 50533 17869 7129 1052 0 29103 0
[pid=21704/tid=21709] ppid=21703 vsize=202132 CPUtime=1.05
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 6197 2205 0 0 102 2 1 0 20 0 2 0 28543195 206983168 17869 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408453720 140198462564679 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) 202132

[startup+6.30025 s]
/proc/loadavg: 1.17 1.07 0.99 2/57 21710
/proc/meminfo: memFree=836776/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=245488 CPUtime=6.26
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 31692 2205 0 0 608 17 1 0 20 0 2 0 28543150 251379712 28713 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 61372 28713 7129 1052 0 39942 0
[pid=21704/tid=21709] ppid=21703 vsize=245488 CPUtime=4.23
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 17048 2205 0 0 414 8 1 0 20 0 2 0 28543195 251379712 28713 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408451960 140198473789873 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) 245488

[startup+12.7003 s]
/proc/loadavg: 1.15 1.07 0.99 2/57 21710
/proc/meminfo: memFree=778744/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=296068 CPUtime=12.63
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 44344 2205 0 0 1235 27 1 0 20 0 2 0 28543150 303173632 41326 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 74017 41326 7129 1052 0 52587 0
[pid=21704/tid=21709] ppid=21703 vsize=296068 CPUtime=10.61
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 29700 2205 0 0 1042 18 1 0 20 0 2 0 28543195 303173632 41326 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408453816 140198507616316 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) 296068

[startup+25.5003 s]
/proc/loadavg: 1.12 1.06 0.99 2/57 21718
/proc/meminfo: memFree=705212/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=363544 CPUtime=25.34
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 61393 2205 0 0 2493 40 1 0 20 0 2 0 28543150 372269056 58193 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 90886 58193 7129 1052 0 69456 0
[pid=21704/tid=21709] ppid=21703 vsize=363544 CPUtime=23.31
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 46749 2205 0 0 2300 30 1 0 20 0 2 0 28543195 372269056 58193 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408453816 140198507881009 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.34
Current children cumulated vsize (KiB) 363544

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

[startup+25.6003 s]
/proc/loadavg: 1.12 1.06 0.99 2/57 21718
/proc/meminfo: memFree=705212/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=364072 CPUtime=25.44
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 61512 2205 0 0 2503 40 1 0 20 0 2 0 28543150 372809728 58312 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 91018 58312 7129 1052 0 69588 0
[pid=21704/tid=21709] ppid=21703 vsize=364072 CPUtime=23.42
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 46868 2205 0 0 2310 31 1 0 20 0 2 0 28543195 372809728 58312 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408451608 140198507762273 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.44
Current children cumulated vsize (KiB) 364072

[startup+38.4003 s]
/proc/loadavg: 1.10 1.06 0.99 2/57 21718
/proc/meminfo: memFree=652016/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=419648 CPUtime=38.18
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 75475 2205 0 0 3762 55 1 0 20 0 2 0 28543150 429719552 72241 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 104912 72241 7143 1052 0 83482 0
[pid=21704/tid=21709] ppid=21703 vsize=419648 CPUtime=36.16
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 60824 2205 0 0 3569 46 1 0 20 0 2 0 28543195 429719552 72241 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408451736 140198507752169 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 38.18
Current children cumulated vsize (KiB) 419648

[startup+44.8003 s]
/proc/loadavg: 1.09 1.06 0.99 2/57 21718
/proc/meminfo: memFree=624488/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=446184 CPUtime=44.56
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 82099 2205 0 0 4390 65 1 0 20 0 2 0 28543150 456892416 78865 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 111546 78865 7143 1052 0 90116 0
[pid=21704/tid=21709] ppid=21703 vsize=446184 CPUtime=42.52
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 67448 2205 0 0 4196 55 1 0 20 0 2 0 28543195 456892416 78865 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408451608 140198507856777 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 44.56
Current children cumulated vsize (KiB) 446184

[startup+46.4002 s]
/proc/loadavg: 1.09 1.06 0.99 2/57 21718
/proc/meminfo: memFree=615064/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=453472 CPUtime=46.15
/proc/21704/stat : 21704 (aptitude) S 21703 21704 17863 34816 17863 4202496 83949 2205 0 0 4548 66 1 0 20 0 2 0 28543150 464355328 80708 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214712688 140198473799243 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 113368 80708 7143 1052 0 91938 0
[pid=21704/tid=21709] ppid=21703 vsize=453472 CPUtime=44.12
/proc/21704/task/21709/stat : 21709 (aptitude) R 21703 21704 17863 34816 17863 4202560 69298 2205 0 0 4355 56 1 0 20 0 2 0 28543195 464355328 80708 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408454184 140198505821158 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.15
Current children cumulated vsize (KiB) 453472

[startup+47.2003 s]
/proc/loadavg: 1.09 1.06 0.99 2/57 21718
/proc/meminfo: memFree=615064/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=455352 CPUtime=46.94
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 84760 2205 0 0 4627 66 1 0 20 0 2 0 28543150 466280448 81394 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214711064 140198507656480 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 113838 81394 7191 1052 0 92401 0
[pid=21704/tid=21709] ppid=21703 vsize=455352 CPUtime=44.5
/proc/21704/task/21709/stat : 21709 (aptitude) S 21703 21704 17863 34816 17863 4202560 69769 2205 0 0 4393 56 1 0 20 0 2 0 28543195 466280448 81394 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408460288 140198473798356 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.94
Current children cumulated vsize (KiB) 455352

[startup+47.6003 s]
/proc/loadavg: 1.08 1.06 0.99 2/57 21718
/proc/meminfo: memFree=610724/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=455420 CPUtime=47.34
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 85278 2205 0 0 4666 67 1 0 20 0 2 0 28543150 466350080 81423 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214711016 140198499897221 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 113855 81423 7192 1052 0 92418 0
[pid=21704/tid=21709] ppid=21703 vsize=455420 CPUtime=44.5
/proc/21704/task/21709/stat : 21709 (aptitude) S 21703 21704 17863 34816 17863 4202560 69769 2205 0 0 4393 56 1 0 20 0 2 0 28543195 466350080 81423 18446744073709551615 140198505054208 140198509361560 140736214720928 140198408460288 140198473798356 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.34
Current children cumulated vsize (KiB) 455420

[startup+48.0005 s]
/proc/loadavg: 1.08 1.06 0.99 2/57 21718
/proc/meminfo: memFree=610724/1022884 swapFree=0/0
[pid=21704] ppid=21703 vsize=279420 CPUtime=47.74
/proc/21704/stat : 21704 (aptitude) R 21703 21704 17863 34816 17863 4202496 87533 2704 0 0 4690 82 1 1 20 0 1 0 28543150 286126080 11799 18446744073709551615 140198505054208 140198509361560 140736214720928 140736214720488 140198462920170 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21704/statm: 69855 11799 1521 1052 0 54111 0
Current children cumulated CPU time (s) 47.74
Current children cumulated vsize (KiB) 279420

Child status: 0
Real time (s): 48.0114
CPU time (s): 47.767
CPU user time (s): 46.9229
CPU system time (s): 0.844052
CPU usage (%): 99.4909
Max. virtual memory (cumulated for all children) (KiB): 455420

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 46.9229
system time used= 0.844052
maximum resident set size= 326040
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 90304
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= 154
involuntary context switches= 989

runsolver used 0.112007 second user time and 0.112007 second system time

The end