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/30.runsolver.aptitude aptitude -s -y --without-recommends install openslp-doc honeyd-common planetpenguin-racer abcmidi-yaps forutil 

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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.14 1.05 0.90 2/55 21101
/proc/meminfo: memFree=907220/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=54860 CPUtime=0
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 596 0 0 0 0 0 0 0 20 0 1 0 28375641 56176640 496 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241199448 140657851377593 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 13715 496 404 1052 0 73 0

[startup+0.132008 s]
/proc/loadavg: 1.14 1.05 0.90 2/55 21101
/proc/meminfo: memFree=907220/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=89152 CPUtime=0.11
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 7771 1709 0 0 10 1 0 0 20 0 1 0 28375641 91291648 7571 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241191504 140657848967239 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 22288 7571 6660 1052 0 858 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 89152

[startup+0.200283 s]
/proc/loadavg: 1.14 1.05 0.90 2/55 21101
/proc/meminfo: memFree=907220/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=89152 CPUtime=0.18
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 7870 1709 0 0 17 1 0 0 20 0 1 0 28375641 91291648 7662 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241190016 140657811148497 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.300267 s]
/proc/loadavg: 1.14 1.05 0.90 2/55 21101
/proc/meminfo: memFree=907220/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=101864 CPUtime=0.28
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 11710 1709 0 0 25 3 0 0 20 0 1 0 28375641 104308736 10756 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241189672 140657848467588 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.700198 s]
/proc/loadavg: 1.14 1.05 0.90 2/55 21101
/proc/meminfo: memFree=907220/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=114096 CPUtime=0.69
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 13701 1709 0 0 63 6 0 0 20 0 2 0 28375641 116834304 12073 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241191512 140657855777885 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 28524 12073 6977 1052 0 7094 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 114096

[startup+1.50024 s]
/proc/loadavg: 1.13 1.05 0.90 2/57 21106
/proc/meminfo: memFree=886512/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=115504 CPUtime=1.49
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 14569 2207 0 0 140 8 1 0 20 0 2 0 28375641 118276096 12314 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241186944 140657811077216 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 28876 12314 7073 1052 0 7446 0
[pid=21101/tid=21106] ppid=21100 vsize=115504 CPUtime=0.01
/proc/21101/task/21106/stat : 21106 (aptitude) S 21100 21101 17863 34816 17863 4202560 6 2207 0 0 0 0 1 0 20 0 2 0 28375685 118276096 12314 18446744073709551615 140657853566976 140657857874328 140735241200240 140657756973056 140657822311124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 115504

[startup+3.10024 s]
/proc/loadavg: 1.13 1.05 0.90 2/57 21107
/proc/meminfo: memFree=869648/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=142484 CPUtime=3.07
/proc/21101/stat : 21101 (aptitude) S 21100 21101 17863 34816 17863 4202496 22319 2207 0 0 296 10 1 0 20 0 2 0 28375641 145903616 19343 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241192000 140657822312011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 35621 19343 7129 1052 0 14191 0
[pid=21101/tid=21106] ppid=21100 vsize=142484 CPUtime=1.22
/proc/21101/task/21106/stat : 21106 (aptitude) R 21100 21101 17863 34816 17863 4202560 7733 2207 0 0 118 3 1 0 20 0 2 0 28375685 145903616 19343 18446744073709551615 140657853566976 140657857874328 140735241200240 140657756963944 140657856151806 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) 142484

[startup+6.30024 s]
/proc/loadavg: 1.12 1.05 0.90 2/57 21107
/proc/meminfo: memFree=832448/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=178320 CPUtime=6.27
/proc/21101/stat : 21101 (aptitude) S 21100 21101 17863 34816 17863 4202496 31421 2207 0 0 612 14 1 0 20 0 2 0 28375641 182599680 28286 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241192000 140657822312011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 44580 28286 7129 1052 0 23150 0
[pid=21101/tid=21106] ppid=21100 vsize=178320 CPUtime=4.41
/proc/21101/task/21106/stat : 21106 (aptitude) R 21100 21101 17863 34816 17863 4202560 16835 2207 0 0 434 6 1 0 20 0 2 0 28375685 182599680 28286 18446744073709551615 140657853566976 140657857874328 140735241200240 140657756964376 140657855777885 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) 178320

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

[startup+6.40031 s]
/proc/loadavg: 1.12 1.05 0.90 2/57 21107
/proc/meminfo: memFree=832448/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=178584 CPUtime=6.37
/proc/21101/stat : 21101 (aptitude) S 21100 21101 17863 34816 17863 4202496 31503 2207 0 0 622 14 1 0 20 0 2 0 28375641 182870016 28368 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241192000 140657822312011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 44646 28368 7129 1052 0 23216 0
[pid=21101/tid=21106] ppid=21100 vsize=178584 CPUtime=4.51
/proc/21101/task/21106/stat : 21106 (aptitude) R 21100 21101 17863 34816 17863 4202560 16917 2207 0 0 444 6 1 0 20 0 2 0 28375685 182870016 28368 18446744073709551615 140657853566976 140657857874328 140735241200240 140657756964376 140657855195313 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.37
Current children cumulated vsize (KiB) 178584

[startup+7.20023 s]
/proc/loadavg: 1.12 1.05 0.90 2/57 21107
/proc/meminfo: memFree=820668/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=186660 CPUtime=7.16
/proc/21101/stat : 21101 (aptitude) S 21100 21101 17863 34816 17863 4202496 33615 2207 0 0 701 14 1 0 20 0 2 0 28375641 191139840 30371 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241192000 140657822312011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 46665 30371 7130 1052 0 25235 0
[pid=21101/tid=21106] ppid=21100 vsize=186660 CPUtime=5.3
/proc/21101/task/21106/stat : 21106 (aptitude) R 21100 21101 17863 34816 17863 4202560 19029 2207 0 0 523 6 1 0 20 0 2 0 28375685 191139840 30371 18446744073709551615 140657853566976 140657857874328 140735241200240 140657756964504 140657856180090 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.16
Current children cumulated vsize (KiB) 186660

[startup+7.60023 s]
/proc/loadavg: 1.12 1.05 0.90 2/57 21107
/proc/meminfo: memFree=820668/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=188088 CPUtime=7.56
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 34704 2207 0 0 741 14 1 0 20 0 2 0 28375641 192602112 30775 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241188104 140657855691910 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 47022 30775 7179 1052 0 25585 0
[pid=21101/tid=21106] ppid=21100 vsize=188088 CPUtime=5.34
/proc/21101/task/21106/stat : 21106 (aptitude) S 21100 21101 17863 34816 17863 4202560 19108 2207 0 0 527 6 1 0 20 0 2 0 28375685 192602112 30775 18446744073709551615 140657853566976 140657857874328 140735241200240 140657756973056 140657822311124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.56
Current children cumulated vsize (KiB) 188088

[startup+7.70024 s]
/proc/loadavg: 1.12 1.05 0.90 2/57 21107
/proc/meminfo: memFree=819552/1022884 swapFree=0/0
[pid=21101] ppid=21100 vsize=180148 CPUtime=7.65
/proc/21101/stat : 21101 (aptitude) R 21100 21101 17863 34816 17863 4202496 35923 2207 0 0 750 14 1 0 20 0 2 0 28375641 184471552 28822 18446744073709551615 140657853566976 140657857874328 140735241200240 140735241192312 140657848464696 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21101/statm: 45037 28822 7179 1052 0 23600 0
[pid=21101/tid=21106] ppid=21100 vsize=180148 CPUtime=5.34
/proc/21101/task/21106/stat : 21106 (aptitude) S 21100 21101 17863 34816 17863 4202560 19108 2207 0 0 527 6 1 0 20 0 2 0 28375685 184471552 28822 18446744073709551615 140657853566976 140657857874328 140735241200240 140657756973056 140657822311124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.65
Current children cumulated vsize (KiB) 180148

Child status: 0
Real time (s): 7.77899
CPU time (s): 7.74848
CPU user time (s): 7.54447
CPU system time (s): 0.204012
CPU usage (%): 99.6078
Max. virtual memory (cumulated for all children) (KiB): 188088

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.54447
system time used= 0.204012
maximum resident set size= 123100
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 38852
page faults= 0
swaps= 0
block input operations= 0
block output operations= 112
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 73
involuntary context switches= 184

runsolver used 0.008 second user time and 0.032002 second system time

The end