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/61.runsolver.aptitude aptitude -s -y --without-recommends install prime-dict pnet-ctools bochs-x php3-cgi memcached 

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.01 1.05 1.01 2/55 23676
/proc/meminfo: memFree=869568/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=54860 CPUtime=0
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 594 0 0 0 0 0 0 0 20 0 1 0 28976222 56176640 494 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712878504 140190965495737 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 13715 494 404 1052 0 73 0

[startup+0.17786 s]
/proc/loadavg: 1.01 1.05 1.01 2/55 23676
/proc/meminfo: memFree=869568/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=100508 CPUtime=0.16
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 10599 1705 0 0 14 2 0 0 20 0 1 0 28976222 102920192 10401 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712870560 140190962509313 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 25127 10401 9226 1052 0 1122 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 100508

[startup+0.200349 s]
/proc/loadavg: 1.01 1.05 1.01 2/55 23676
/proc/meminfo: memFree=869568/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=100508 CPUtime=0.18
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 10605 1705 0 0 16 2 0 0 20 0 1 0 28976222 102920192 10407 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712870560 140190962528434 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300265 s]
/proc/loadavg: 1.01 1.05 1.01 2/55 23676
/proc/meminfo: memFree=869568/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=111108 CPUtime=0.28
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 11876 1705 0 0 26 2 0 0 20 0 1 0 28976222 113774592 11670 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712870888 140190969816684 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 27777 11670 9302 1052 0 3772 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 111108

[startup+0.700206 s]
/proc/loadavg: 1.01 1.05 1.01 2/55 23676
/proc/meminfo: memFree=869568/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=123288 CPUtime=0.68
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 17027 1705 0 0 61 7 0 0 20 0 2 0 28976222 126246912 14303 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712875080 140190962528090 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.01 1.05 1.01 2/57 23681
/proc/meminfo: memFree=841288/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=132392 CPUtime=1.48
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 19434 1705 0 0 140 8 0 0 20 0 2 0 28976222 135569408 16705 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712869648 140190925185296 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 33098 16705 9585 1052 0 9093 0
[pid=23676/tid=23681] ppid=23675 vsize=132392 CPUtime=0
/proc/23676/task/23681/stat : 23681 (aptitude) S 23675 23676 17863 34816 17863 4202560 4 1705 0 0 0 0 0 0 20 0 2 0 28976288 135569408 16705 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858512384 140190936429268 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) 132392

[startup+3.10025 s]
/proc/loadavg: 1.01 1.05 1.01 2/57 23682
/proc/meminfo: memFree=840040/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=133800 CPUtime=3.08
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 20590 2204 0 0 296 11 1 0 20 0 2 0 28976222 137011200 16944 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712866112 140190933990366 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 33450 16944 9644 1052 0 9445 0
[pid=23676/tid=23681] ppid=23675 vsize=133800 CPUtime=0.01
/proc/23676/task/23681/stat : 23681 (aptitude) S 23675 23676 17863 34816 17863 4202560 6 2204 0 0 0 0 1 0 20 0 2 0 28976288 137011200 16944 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858512384 140190936429268 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) 133800

[startup+6.30025 s]
/proc/loadavg: 1.09 1.06 1.01 2/57 23682
/proc/meminfo: memFree=796648/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=245556 CPUtime=6.26
/proc/23676/stat : 23676 (aptitude) S 23675 23676 17863 34816 17863 4202496 33142 2204 0 0 609 16 1 0 20 0 2 0 28976222 251449344 28726 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712871056 140190936430155 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 61389 28726 9700 1052 0 37384 0
[pid=23676/tid=23681] ppid=23675 vsize=245556 CPUtime=3.17
/proc/23676/task/23681/stat : 23681 (aptitude) R 23675 23676 17863 34816 17863 4202560 12551 2204 0 0 311 5 1 0 20 0 2 0 28976288 251449344 28726 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858503704 140190970576275 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) 245556

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

[startup+6.40031 s]
/proc/loadavg: 1.09 1.06 1.01 2/57 23682
/proc/meminfo: memFree=796648/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=245820 CPUtime=6.36
/proc/23676/stat : 23676 (aptitude) S 23675 23676 17863 34816 17863 4202496 33222 2204 0 0 619 16 1 0 20 0 2 0 28976222 251719680 28806 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712871056 140190936430155 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 61455 28806 9700 1052 0 37450 0
[pid=23676/tid=23681] ppid=23675 vsize=245820 CPUtime=3.27
/proc/23676/task/23681/stat : 23681 (aptitude) R 23675 23676 17863 34816 17863 4202560 12631 2204 0 0 321 5 1 0 20 0 2 0 28976288 251719680 28806 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858503752 140190933994475 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.36
Current children cumulated vsize (KiB) 245820

[startup+9.60024 s]
/proc/loadavg: 1.09 1.06 1.01 2/57 23682
/proc/meminfo: memFree=779536/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=267224 CPUtime=9.55
/proc/23676/stat : 23676 (aptitude) S 23675 23676 17863 34816 17863 4202496 38686 2204 0 0 936 18 1 0 20 0 2 0 28976222 273637376 34124 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712871056 140190936430155 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 66806 34124 9700 1052 0 42801 0
[pid=23676/tid=23681] ppid=23675 vsize=267224 CPUtime=6.45
/proc/23676/task/23681/stat : 23681 (aptitude) R 23675 23676 17863 34816 17863 4202560 18095 2204 0 0 638 6 1 0 20 0 2 0 28976288 273637376 34124 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858503704 140190925195641 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.55
Current children cumulated vsize (KiB) 267224

[startup+10.4002 s]
/proc/loadavg: 1.08 1.06 1.01 2/57 23682
/proc/meminfo: memFree=768748/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=273956 CPUtime=10.34
/proc/23676/stat : 23676 (aptitude) S 23675 23676 17863 34816 17863 4202496 40392 2204 0 0 1014 19 1 0 20 0 2 0 28976222 280530944 35828 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712871056 140190936430155 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 68489 35828 9700 1052 0 44484 0
[pid=23676/tid=23681] ppid=23675 vsize=273956 CPUtime=7.25
/proc/23676/task/23681/stat : 23681 (aptitude) R 23675 23676 17863 34816 17863 4202560 19801 2204 0 0 716 8 1 0 20 0 2 0 28976288 280530944 35828 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858503704 140190963085329 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) 273956

[startup+11.2002 s]
/proc/loadavg: 1.08 1.06 1.01 2/57 23682
/proc/meminfo: memFree=761060/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=276656 CPUtime=11.14
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 43827 2204 0 0 1093 20 1 0 20 0 2 0 28976222 283295744 36715 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712871000 140190962581639 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 69164 36715 9749 1052 0 45152 0
[pid=23676/tid=23681] ppid=23675 vsize=276656 CPUtime=7.62
/proc/23676/task/23681/stat : 23681 (aptitude) S 23675 23676 17863 34816 17863 4202560 20467 2204 0 0 753 8 1 0 20 0 2 0 28976288 283295744 36715 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858512384 140190936429268 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.14
Current children cumulated vsize (KiB) 276656

[startup+11.4002 s]
/proc/loadavg: 1.08 1.06 1.01 2/57 23682
/proc/meminfo: memFree=761060/1022884 swapFree=0/0
[pid=23676] ppid=23675 vsize=276656 CPUtime=11.34
/proc/23676/stat : 23676 (aptitude) R 23675 23676 17863 34816 17863 4202496 44106 2704 0 0 1107 25 1 1 20 0 2 0 28976222 283295744 36858 18446744073709551615 140190967685120 140190971992472 140734712879296 140734712869384 140190962414145 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23676/statm: 69164 36858 9749 1052 0 45152 0
[pid=23676/tid=23681] ppid=23675 vsize=276656 CPUtime=7.63
/proc/23676/task/23681/stat : 23681 (aptitude) S 23675 23676 17863 34816 17863 4202560 20467 2704 0 0 753 8 1 1 20 0 2 0 28976288 283295744 36858 18446744073709551615 140190967685120 140190971992472 140734712879296 140190858512384 140190936429268 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.34
Current children cumulated vsize (KiB) 276656

Child status: 0
Real time (s): 11.4886
CPU time (s): 11.4407
CPU user time (s): 11.1287
CPU system time (s): 0.312019
CPU usage (%): 99.5832
Max. virtual memory (cumulated for all children) (KiB): 276656

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 11.1287
system time used= 0.312019
maximum resident set size= 147452
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 47351
page faults= 0
swaps= 0
block input operations= 0
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 78
involuntary context switches= 245

runsolver used 0.012 second user time and 0.044002 second system time

The end