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-sid/logs/64.runsolver.aptitude aptitude -s -y --without-recommends install lg-issue103 rbldnsd libexpat-ocaml kernel-headers-2.6.8-13-em64t-p4 mergelog 

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.2022 s]
/proc/loadavg: 1.22 1.10 1.05 2/55 25788
/proc/meminfo: memFree=832512/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=103288 CPUtime=0.17
/proc/25788/stat : 25788 (aptitude) R 25787 25788 17863 34816 17863 4202496 11295 1709 0 0 15 2 0 0 20 0 1 0 29630447 105766912 11095 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067250992 139988166086384 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 25822 11095 9884 1052 0 1159 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 103288

[startup+0.300284 s]
/proc/loadavg: 1.22 1.10 1.05 2/55 25788
/proc/meminfo: memFree=832512/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=103288 CPUtime=0.27
/proc/25788/stat : 25788 (aptitude) R 25787 25788 17863 34816 17863 4202496 11307 1709 0 0 25 2 0 0 20 0 1 0 29630447 105766912 11107 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067250992 139988172219952 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 25822 11107 9896 1052 0 1159 0
Current children cumulated CPU time (s) 0.27
Current children cumulated vsize (KiB) 103288

[startup+0.400275 s]
/proc/loadavg: 1.22 1.10 1.05 2/55 25788
/proc/meminfo: memFree=832512/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=114256 CPUtime=0.36
/proc/25788/stat : 25788 (aptitude) R 25787 25788 17863 34816 17863 4202496 14144 1709 0 0 34 2 0 0 20 0 1 0 29630447 116998144 13935 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067248872 139988166791035 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 28564 13935 9966 1052 0 3901 0
Current children cumulated CPU time (s) 0.36
Current children cumulated vsize (KiB) 114256

[startup+0.700202 s]
/proc/loadavg: 1.22 1.10 1.05 2/55 25788
/proc/meminfo: memFree=832512/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=123068 CPUtime=0.66
/proc/25788/stat : 25788 (aptitude) R 25787 25788 17863 34816 17863 4202496 17688 1709 0 0 61 5 0 0 20 0 1 0 29630447 126021632 15964 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067249160 139988128931359 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 30767 15964 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.66
Current children cumulated vsize (KiB) 123068

[startup+1.50023 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25793
/proc/meminfo: memFree=803240/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=135988 CPUtime=1.46
/proc/25788/stat : 25788 (aptitude) R 25787 25788 17863 34816 17863 4202496 20674 1709 0 0 140 6 0 0 20 0 2 0 29630447 139251712 17591 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067246600 139988129543504 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 33997 17591 10244 1052 0 9334 0
[pid=25788/tid=25793] ppid=25787 vsize=135988 CPUtime=0
/proc/25788/task/25793/stat : 25793 (aptitude) S 25787 25788 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29630525 139251712 17591 18446744073709551615 139988171390976 139988175698328 140737067259728 139988059068416 139988140135124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 135988

[startup+3.10025 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25794
/proc/meminfo: memFree=801868/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=142988 CPUtime=3.05
/proc/25788/stat : 25788 (aptitude) S 25787 25788 17863 34816 17863 4202496 24047 2208 0 0 297 8 0 0 20 0 2 0 29630447 146419712 19447 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067251488 139988140136011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 35747 19447 10350 1052 0 11084 0
[pid=25788/tid=25793] ppid=25787 vsize=142988 CPUtime=0.17
/proc/25788/task/25793/stat : 25793 (aptitude) R 25787 25788 17863 34816 17863 4202560 2326 2208 0 0 17 0 0 0 20 0 2 0 29630525 146419712 19447 18446744073709551615 139988171390976 139988175698328 140737067259728 139988059059304 139988128901256 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 142988

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

[startup+3.30025 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25794
/proc/meminfo: memFree=801868/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=146976 CPUtime=3.25
/proc/25788/stat : 25788 (aptitude) R 25787 25788 17863 34816 17863 4202496 26038 2208 0 0 317 8 0 0 20 0 2 0 29630447 150503424 20490 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067249560 139988166244322 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 36744 20490 10401 1052 0 12074 0
[pid=25788/tid=25793] ppid=25787 vsize=146976 CPUtime=0.33
/proc/25788/task/25793/stat : 25793 (aptitude) S 25787 25788 17863 34816 17863 4202560 3453 2208 0 0 33 0 0 0 20 0 2 0 29630525 150503424 20490 18446744073709551615 139988171390976 139988175698328 140737067259728 139988059068416 139988140135124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.25
Current children cumulated vsize (KiB) 146976

[startup+3.50333 s]
/proc/loadavg: 1.21 1.10 1.05 2/57 25794
/proc/meminfo: memFree=791584/1022884 swapFree=0/0
[pid=25788] ppid=25787 vsize=146976 CPUtime=3.45
/proc/25788/stat : 25788 (aptitude) R 25787 25788 17863 34816 17863 4202496 27757 2208 0 0 336 9 0 0 20 0 2 0 29630447 150503424 20490 18446744073709551615 139988171390976 139988175698328 140737067259728 140737067249488 139988129093942 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25788/statm: 36744 20490 10401 1052 0 12074 0
[pid=25788/tid=25793] ppid=25787 vsize=146976 CPUtime=0.33
/proc/25788/task/25793/stat : 25793 (aptitude) S 25787 25788 17863 34816 17863 4202560 3453 2208 0 0 33 0 0 0 20 0 2 0 29630525 150503424 20490 18446744073709551615 139988171390976 139988175698328 140737067259728 139988059068416 139988140135124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.45
Current children cumulated vsize (KiB) 146976

Child status: 0
Real time (s): 3.54234
CPU time (s): 3.51222
CPU user time (s): 3.38021
CPU system time (s): 0.132008
CPU usage (%): 99.1497
Max. virtual memory (cumulated for all children) (KiB): 146976

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.38021
system time used= 0.132008
maximum resident set size= 81972
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 30701
page faults= 0
swaps= 0
block input operations= 0
block output operations= 16
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 62
involuntary context switches= 107

runsolver used 0 second user time and 0.024001 second system time

The end