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/117.runsolver.aptitude aptitude -s -y --without-recommends remove gnupg-agent imlib-base kdetoys libxml2-utils libcurl3 

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.09 1.07 1.07 2/55 26699
/proc/meminfo: memFree=833384/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=3152 CPUtime=0
/proc/26699/stat : 26699 (runsolver) R 26698 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29914023 3227648 32 18446744073709551615 134512640 134586868 4288949824 4288947872 4151227440 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.18203 s]
/proc/loadavg: 1.09 1.07 1.07 2/55 26699
/proc/meminfo: memFree=833384/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=103288 CPUtime=0.17
/proc/26699/stat : 26699 (aptitude) R 26698 26699 17863 34816 17863 4202496 11295 1710 0 0 14 3 0 0 20 0 1 0 29914023 105766912 11096 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643236848 140221459106731 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 25822 11096 9884 1052 0 1159 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 103288

[startup+0.200308 s]
/proc/loadavg: 1.09 1.07 1.07 2/55 26699
/proc/meminfo: memFree=833384/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=103288 CPUtime=0.18
/proc/26699/stat : 26699 (aptitude) R 26698 26699 17863 34816 17863 4202496 11300 1710 0 0 15 3 0 0 20 0 1 0 29914023 105766912 11101 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643236848 140221459122670 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300271 s]
/proc/loadavg: 1.09 1.07 1.07 2/55 26699
/proc/meminfo: memFree=833384/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=103288 CPUtime=0.28
/proc/26699/stat : 26699 (aptitude) R 26698 26699 17863 34816 17863 4202496 11308 1710 0 0 25 3 0 0 20 0 1 0 29914023 105766912 11109 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643236848 140221459122765 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 25822 11109 9897 1052 0 1159 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103288

[startup+0.700206 s]
/proc/loadavg: 1.09 1.07 1.07 2/55 26699
/proc/meminfo: memFree=833384/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=123068 CPUtime=0.68
/proc/26699/stat : 26699 (aptitude) R 26698 26699 17863 34816 17863 4202496 17689 1710 0 0 60 8 0 0 20 0 1 0 29914023 126021632 15965 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643235016 140221421821442 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.09 1.07 1.07 2/57 26704
/proc/meminfo: memFree=804236/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=135852 CPUtime=1.48
/proc/26699/stat : 26699 (aptitude) R 26698 26699 17863 34816 17863 4202496 20627 1710 0 0 139 9 0 0 20 0 2 0 29914023 139112448 17544 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643233352 140221459108848 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 33963 17544 10227 1052 0 9300 0
[pid=26699/tid=26704] ppid=26698 vsize=135852 CPUtime=0
/proc/26699/task/26704/stat : 26704 (aptitude) S 26698 26699 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29914100 139112448 17544 18446744073709551615 140221464281088 140221468588440 140734643245584 140221351958528 140221433025236 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) 135852

[startup+3.10024 s]
/proc/loadavg: 1.09 1.07 1.07 2/57 26704
/proc/meminfo: memFree=803368/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=144832 CPUtime=3.07
/proc/26699/stat : 26699 (aptitude) S 26698 26699 17863 34816 17863 4202496 22984 1710 0 0 298 9 0 0 20 0 2 0 29914023 148307968 19900 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643237344 140221433026123 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 36208 19900 10319 1052 0 11545 0
[pid=26699/tid=26704] ppid=26698 vsize=144832 CPUtime=0.27
/proc/26699/task/26704/stat : 26704 (aptitude) R 26698 26699 17863 34816 17863 4202560 2199 1710 0 0 27 0 0 0 20 0 2 0 29914100 148307968 19900 18446744073709551615 140221464281088 140221468588440 140734643245584 140221351950200 140221466907282 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) 144832

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

[startup+3.20032 s]
/proc/loadavg: 1.09 1.07 1.07 2/57 26704
/proc/meminfo: memFree=803368/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=146812 CPUtime=3.17
/proc/26699/stat : 26699 (aptitude) S 26698 26699 17863 34816 17863 4202496 23461 1710 0 0 307 10 0 0 20 0 2 0 29914023 150335488 20377 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643237344 140221433026123 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 36703 20377 10319 1052 0 12040 0
[pid=26699/tid=26704] ppid=26698 vsize=146812 CPUtime=0.37
/proc/26699/task/26704/stat : 26704 (aptitude) R 26698 26699 17863 34816 17863 4202560 2676 1710 0 0 36 1 0 0 20 0 2 0 29914100 150335488 20377 18446744073709551615 140221464281088 140221468588440 140734643245584 140221351948344 140221466914144 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.17
Current children cumulated vsize (KiB) 146812

[startup+4.00024 s]
/proc/loadavg: 1.09 1.07 1.07 2/57 26704
/proc/meminfo: memFree=790720/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=157636 CPUtime=3.96
/proc/26699/stat : 26699 (aptitude) S 26698 26699 17863 34816 17863 4202496 26156 1710 0 0 384 12 0 0 20 0 2 0 29914023 161419264 23072 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643237344 140221433026123 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 39409 23072 10320 1052 0 14746 0
[pid=26699/tid=26704] ppid=26698 vsize=157636 CPUtime=1.16
/proc/26699/task/26704/stat : 26704 (aptitude) R 26698 26699 17863 34816 17863 4202560 5370 1710 0 0 113 3 0 0 20 0 2 0 29914100 161419264 23072 18446744073709551615 140221464281088 140221468588440 140734643245584 140221351951960 140221466510042 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.96
Current children cumulated vsize (KiB) 157636

[startup+4.40025 s]
/proc/loadavg: 1.08 1.07 1.07 2/57 26704
/proc/meminfo: memFree=781048/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=158560 CPUtime=4.37
/proc/26699/stat : 26699 (aptitude) S 26698 26699 17863 34816 17863 4202496 26402 1710 0 0 424 13 0 0 20 0 2 0 29914023 162365440 23318 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643237344 140221433026123 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 39640 23318 10320 1052 0 14977 0
[pid=26699/tid=26704] ppid=26698 vsize=158560 CPUtime=1.57
/proc/26699/task/26704/stat : 26704 (aptitude) R 26698 26699 17863 34816 17863 4202560 5616 1710 0 0 153 4 0 0 20 0 2 0 29914100 162365440 23318 18446744073709551615 140221464281088 140221468588440 140734643245584 140221351951960 140221421791363 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.37
Current children cumulated vsize (KiB) 158560

[startup+4.80025 s]
/proc/loadavg: 1.08 1.07 1.07 2/57 26704
/proc/meminfo: memFree=781048/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=161360 CPUtime=4.76
/proc/26699/stat : 26699 (aptitude) R 26698 26699 17863 34816 17863 4202496 27160 1710 0 0 463 13 0 0 20 0 2 0 29914023 165232640 24074 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643233448 140221466487360 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 40340 24074 10370 1052 0 15670 0
[pid=26699/tid=26704] ppid=26698 vsize=161360 CPUtime=1.84
/proc/26699/task/26704/stat : 26704 (aptitude) S 26698 26699 17863 34816 17863 4202560 6318 1710 0 0 180 4 0 0 20 0 2 0 29914100 165232640 24074 18446744073709551615 140221464281088 140221468588440 140734643245584 140221351958528 140221433025236 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.76
Current children cumulated vsize (KiB) 161360

[startup+4.90025 s]
/proc/loadavg: 1.08 1.07 1.07 2/57 26704
/proc/meminfo: memFree=781048/1022884 swapFree=0/0
[pid=26699] ppid=26698 vsize=161360 CPUtime=4.86
/proc/26699/stat : 26699 (aptitude) R 26698 26699 17863 34816 17863 4202496 27160 1710 0 0 473 13 0 0 20 0 2 0 29914023 165232640 24074 18446744073709551615 140221464281088 140221468588440 140734643245584 140734643233448 140221466487583 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26699/statm: 40340 24074 10370 1052 0 15670 0
[pid=26699/tid=26704] ppid=26698 vsize=161360 CPUtime=1.84
/proc/26699/task/26704/stat : 26704 (aptitude) S 26698 26699 17863 34816 17863 4202560 6318 1710 0 0 180 4 0 0 20 0 2 0 29914100 165232640 24074 18446744073709551615 140221464281088 140221468588440 140734643245584 140221351958528 140221433025236 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.86
Current children cumulated vsize (KiB) 161360

Child status: 0
Real time (s): 4.94402
CPU time (s): 4.92431
CPU user time (s): 4.7603
CPU system time (s): 0.16401
CPU usage (%): 99.6012
Max. virtual memory (cumulated for all children) (KiB): 161360

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.7603
system time used= 0.16401
maximum resident set size= 96312
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 28939
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 57
involuntary context switches= 129

runsolver used 0 second user time and 0.028001 second system time

The end