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/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.16 1.04 0.95 2/55 21611
/proc/meminfo: memFree=977656/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=3152 CPUtime=0
/proc/21611/stat : 21611 (runsolver) R 21610 21611 17863 34816 17863 4202560 77 0 0 0 0 0 0 0 20 0 1 0 28500481 3227648 98 18446744073709551615 134512640 134586868 4294813232 4294811256 4149515167 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21611/statm: 788 98 66 19 0 73 0

[startup+0.152715 s]
/proc/loadavg: 1.16 1.04 0.95 2/55 21611
/proc/meminfo: memFree=977656/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=17468 CPUtime=0
/proc/21611/stat : 21611 (aptitude) D 21610 21611 17863 34816 17863 4202496 135 0 7 0 0 0 0 0 20 0 1 0 28500481 17887232 57 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715857800 140528854230406 0 0 0 0 0 0 0 17 0 0 0 14 0 0
/proc/21611/statm: 4367 57 40 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 17468

[startup+0.200437 s]
/proc/loadavg: 1.16 1.04 0.95 2/55 21611
/proc/meminfo: memFree=977656/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=33024 CPUtime=0
/proc/21611/stat : 21611 (aptitude) D 21610 21611 17863 34816 17863 4202496 163 0 12 0 0 0 0 0 20 0 1 0 28500481 33816576 85 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715857416 140528854230563 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/21611/statm: 8256 85 55 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 33024

[startup+0.300398 s]
/proc/loadavg: 1.16 1.04 0.95 2/55 21611
/proc/meminfo: memFree=977656/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=54968 CPUtime=0
/proc/21611/stat : 21611 (aptitude) D 21610 21611 17863 34816 17863 4202496 835 0 25 0 0 0 0 0 20 0 1 0 28500481 56287232 751 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715860472 140528822363072 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/21611/statm: 13742 751 612 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700319 s]
/proc/loadavg: 1.16 1.04 0.95 2/55 21611
/proc/meminfo: memFree=977656/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=87116 CPUtime=0.01
/proc/21611/stat : 21611 (aptitude) D 21610 21611 17863 34816 17863 4202496 1540 1705 43 4 0 1 0 0 20 0 1 0 28500481 89206784 1385 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715855248 140528814059365 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/21611/statm: 21779 1385 984 1052 0 349 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 87116

[startup+1.5003 s]
/proc/loadavg: 1.16 1.04 0.95 1/56 21615
/proc/meminfo: memFree=969084/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=89152 CPUtime=0.02
/proc/21611/stat : 21611 (aptitude) D 21610 21611 17863 34816 17863 4202496 3024 1705 176 4 0 2 0 0 20 0 1 0 28500481 91291648 2999 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715852464 140528851421082 0 134217728 4096 0 0 0 0 17 0 0 0 142 0 0
/proc/21611/statm: 22288 2999 2089 1052 0 858 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 89152

[startup+3.10027 s]
/proc/loadavg: 1.16 1.04 0.95 2/56 21615
/proc/meminfo: memFree=958048/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=114112 CPUtime=0.77
/proc/21611/stat : 21611 (aptitude) R 21610 21611 17863 34816 17863 4202496 13452 1705 252 4 69 8 0 0 20 0 2 0 28500481 116850688 12076 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715852264 140528858582109 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 227 0 0
/proc/21611/statm: 28528 12076 6977 1052 0 7098 0
Current children cumulated CPU time (s) 0.77
Current children cumulated vsize (KiB) 114112
heavy processes:

[startup+6.30031 s]
/proc/loadavg: 1.31 1.08 0.96 2/57 21617
/proc/meminfo: memFree=860824/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=218424 CPUtime=3.87
/proc/21611/stat : 21611 (aptitude) S 21610 21611 17863 34816 17863 4202496 24698 2202 255 6 374 12 0 1 20 0 2 0 28500481 223666176 21949 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715852752 140528825116235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/21611/statm: 54606 21949 7130 1052 0 33176 0
[pid=21611/tid=21616] ppid=21610 vsize=218424 CPUtime=2.02
/proc/21611/task/21616/stat : 21616 (aptitude) R 21610 21611 17863 34816 17863 4202560 10359 2202 3 6 199 2 0 1 20 0 2 0 28500757 223666176 21949 18446744073709551615 140528856371200 140528860678552 140734715860992 140528759768248 140528859017655 0 134217728 4096 0 0 0 0 -1 0 0 0 5 0 0
Current children cumulated CPU time (s) 3.87
Current children cumulated vsize (KiB) 218424
heavy processes:

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

[startup+6.40745 s]
/proc/loadavg: 1.31 1.08 0.96 2/57 21617
/proc/meminfo: memFree=851524/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=219480 CPUtime=3.98
/proc/21611/stat : 21611 (aptitude) S 21610 21611 17863 34816 17863 4202496 24942 2202 255 6 385 12 0 1 20 0 2 0 28500481 224747520 22193 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715852752 140528825116235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/21611/statm: 54870 22193 7130 1052 0 33440 0
[pid=21611/tid=21616] ppid=21610 vsize=219480 CPUtime=2.13
/proc/21611/task/21616/stat : 21616 (aptitude) R 21610 21611 17863 34816 17863 4202560 10603 2202 3 6 210 2 0 1 20 0 2 0 28500757 224747520 22193 18446744073709551615 140528856371200 140528860678552 140734715860992 140528759770808 140528858995762 0 134217728 4096 0 0 0 0 -1 0 0 0 5 0 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 219480

[startup+8.0003 s]
/proc/loadavg: 1.31 1.08 0.96 2/57 21617
/proc/meminfo: memFree=838132/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=236616 CPUtime=5.56
/proc/21611/stat : 21611 (aptitude) S 21610 21611 17863 34816 17863 4202496 29284 2202 255 6 542 13 0 1 20 0 2 0 28500481 242294784 26488 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715852752 140528825116235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/21611/statm: 59154 26488 7130 1052 0 37724 0
[pid=21611/tid=21616] ppid=21610 vsize=236616 CPUtime=3.71
/proc/21611/task/21616/stat : 21616 (aptitude) R 21610 21611 17863 34816 17863 4202560 14945 2202 3 6 366 4 0 1 20 0 2 0 28500757 242294784 26488 18446744073709551615 140528856371200 140528860678552 140734715860992 140528759770808 140528859017616 0 134217728 4096 0 0 0 0 -1 0 0 0 5 0 0
Current children cumulated CPU time (s) 5.56
Current children cumulated vsize (KiB) 236616

[startup+9.6003 s]
/proc/loadavg: 1.28 1.08 0.96 2/57 21617
/proc/meminfo: memFree=824864/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=252624 CPUtime=7.15
/proc/21611/stat : 21611 (aptitude) S 21610 21611 17863 34816 17863 4202496 33478 2202 255 6 697 17 0 1 20 0 2 0 28500481 258686976 30481 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715852752 140528825116235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 231 0 0
/proc/21611/statm: 63156 30481 7131 1052 0 41726 0
[pid=21611/tid=21616] ppid=21610 vsize=252624 CPUtime=5.31
/proc/21611/task/21616/stat : 21616 (aptitude) R 21610 21611 17863 34816 17863 4202560 19139 2202 3 6 522 8 0 1 20 0 2 0 28500757 258686976 30481 18446744073709551615 140528856371200 140528860678552 140734715860992 140528759768600 140528859200080 0 134217728 4096 0 0 0 0 -1 0 0 0 5 0 0
Current children cumulated CPU time (s) 7.15
Current children cumulated vsize (KiB) 252624

[startup+10.4003 s]
/proc/loadavg: 1.28 1.08 0.96 1/57 21617
/proc/meminfo: memFree=814076/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=255744 CPUtime=7.87
/proc/21611/stat : 21611 (aptitude) R 21610 21611 17863 34816 17863 4202496 36513 2202 266 6 768 18 0 1 20 0 2 0 28500481 261881856 31467 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715852696 140528851263824 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 237 0 0
/proc/21611/statm: 63936 31467 7180 1052 0 42499 0
[pid=21611/tid=21616] ppid=21610 vsize=255744 CPUtime=5.57
/proc/21611/task/21616/stat : 21616 (aptitude) S 21610 21611 17863 34816 17863 4202560 19894 2202 4 6 548 8 0 1 20 0 2 0 28500757 261881856 31467 18446744073709551615 140528856371200 140528860678552 140734715860992 140528759777280 140528825115348 0 134217728 4096 0 0 0 0 -1 0 0 0 7 0 0
Current children cumulated CPU time (s) 7.87
Current children cumulated vsize (KiB) 255744

[startup+10.6002 s]
/proc/loadavg: 1.28 1.08 0.96 1/57 21617
/proc/meminfo: memFree=814076/1022884 swapFree=0/0
[pid=21611] ppid=21610 vsize=138932 CPUtime=7.97
/proc/21611/stat : 21611 (aptitude) D 21610 21611 17863 34816 17863 4202496 37243 2703 277 6 771 24 0 2 20 0 1 0 28500481 142266368 2219 18446744073709551615 140528856371200 140528860678552 140734715860992 140734715860064 140528834861824 0 134217728 4096 0 0 0 0 17 0 0 0 246 0 0
/proc/21611/statm: 34733 2219 1530 1052 0 18989 0
Current children cumulated CPU time (s) 7.97
Current children cumulated vsize (KiB) 138932

Child status: 0
Real time (s): 10.6095
CPU time (s): 7.9885
CPU user time (s): 7.72048
CPU system time (s): 0.268016
CPU usage (%): 75.2956
Max. virtual memory (cumulated for all children) (KiB): 255744

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.72048
system time used= 0.268016
maximum resident set size= 126216
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 39964
page faults= 285
swaps= 0
block input operations= 135696
block output operations= 112
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1551
involuntary context switches= 200

runsolver used 0.020001 second user time and 0.044002 second system time

The end