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/logs/82.runsolver.aptitude aptitude -s -y --without-recommends install libant1.5-java dpsyco-ssh coco-java netwag mp3splt 

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: 0.99 0.74 0.34 2/55 19953
/proc/meminfo: memFree=244208/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=54860 CPUtime=0
/proc/19953/stat : 19953 (aptitude) R 19952 19953 17863 34816 17863 4202496 592 0 0 0 0 0 0 0 20 0 1 0 28202999 56176640 492 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769845016 140491962942912 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 13715 492 403 1052 0 73 0

[startup+0.19544 s]
/proc/loadavg: 0.99 0.74 0.34 2/55 19953
/proc/meminfo: memFree=244208/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=89348 CPUtime=0.18
/proc/19953/stat : 19953 (aptitude) R 19952 19953 17863 34816 17863 4202496 8314 1707 0 0 15 3 0 0 20 0 1 0 28202999 91492352 7359 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769835320 140491959949428 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 22337 7359 4721 1052 0 2928 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89348

[startup+0.20027 s]
/proc/loadavg: 0.99 0.74 0.34 2/55 19953
/proc/meminfo: memFree=244208/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=89348 CPUtime=0.18
/proc/19953/stat : 19953 (aptitude) R 19952 19953 17863 34816 17863 4202496 8316 1707 0 0 15 3 0 0 20 0 1 0 28202999 91492352 7361 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769835320 140491968071655 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 22337 7361 4721 1052 0 2928 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89348

[startup+0.300251 s]
/proc/loadavg: 0.99 0.74 0.34 2/55 19953
/proc/meminfo: memFree=244208/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=96684 CPUtime=0.28
/proc/19953/stat : 19953 (aptitude) R 19952 19953 17863 34816 17863 4202496 9022 1707 0 0 23 5 0 0 20 0 2 0 28202999 99004416 7655 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769841592 140491960532864 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 24171 7655 4890 1052 0 4762 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 96684

[startup+0.700201 s]
/proc/loadavg: 0.99 0.74 0.34 2/55 19953
/proc/meminfo: memFree=244208/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=100676 CPUtime=0.68
/proc/19953/stat : 19953 (aptitude) R 19952 19953 17863 34816 17863 4202496 10141 1707 0 0 63 5 0 0 20 0 2 0 28202999 103092224 8770 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769832968 140491922643271 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 25169 8770 4994 1052 0 5760 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 100676

[startup+1.50024 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19959
/proc/meminfo: memFree=228328/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=112704 CPUtime=1.47
/proc/19953/stat : 19953 (aptitude) S 19952 19953 17863 34816 17863 4202496 14280 2205 0 0 141 6 0 0 20 0 2 0 28202999 115408896 11910 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769837568 140491933877835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 28176 11910 5107 1052 0 8767 0
[pid=19953/tid=19958] ppid=19952 vsize=112704 CPUtime=0.29
/proc/19953/task/19958/stat : 19958 (aptitude) R 19952 19953 17863 34816 17863 4202560 3554 2205 0 0 29 0 0 0 20 0 2 0 28203028 115408896 11910 18446744073709551615 140491965132800 140491969440152 140735769845808 140491881705640 140491965961789 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 112704

[startup+3.10025 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19959
/proc/meminfo: memFree=206008/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=195432 CPUtime=3.07
/proc/19953/stat : 19953 (aptitude) S 19952 19953 17863 34816 17863 4202496 18604 2205 0 0 300 7 0 0 20 0 2 0 28202999 200122368 16199 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769837568 140491933877835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 48858 16199 5108 1052 0 29449 0
[pid=19953/tid=19958] ppid=19952 vsize=195432 CPUtime=1.89
/proc/19953/task/19958/stat : 19958 (aptitude) R 19952 19953 17863 34816 17863 4202560 7876 2205 0 0 188 1 0 0 20 0 2 0 28203028 200122368 16199 18446744073709551615 140491965132800 140491969440152 140735769845808 140491881703208 140491967748992 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) 195432

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

[startup+3.20037 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19959
/proc/meminfo: memFree=206008/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=196360 CPUtime=3.17
/proc/19953/stat : 19953 (aptitude) S 19952 19953 17863 34816 17863 4202496 18817 2205 0 0 310 7 0 0 20 0 2 0 28202999 201072640 16412 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769837568 140491933877835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 49090 16412 5108 1052 0 29681 0
[pid=19953/tid=19958] ppid=19952 vsize=196360 CPUtime=1.99
/proc/19953/task/19958/stat : 19958 (aptitude) R 19952 19953 17863 34816 17863 4202560 8089 2205 0 0 198 1 0 0 20 0 2 0 28203028 201072640 16412 18446744073709551615 140491965132800 140491969440152 140735769845808 140491881703064 140491923285239 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) 196360

[startup+4.00025 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19959
/proc/meminfo: memFree=197824/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=202052 CPUtime=3.96
/proc/19953/stat : 19953 (aptitude) S 19952 19953 17863 34816 17863 4202496 20301 2205 0 0 389 7 0 0 20 0 2 0 28202999 206901248 17833 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769837568 140491933877835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 50513 17833 5109 1052 0 31104 0
[pid=19953/tid=19958] ppid=19952 vsize=202052 CPUtime=2.78
/proc/19953/task/19958/stat : 19958 (aptitude) R 19952 19953 17863 34816 17863 4202560 9573 2205 0 0 277 1 0 0 20 0 2 0 28203028 206901248 17833 18446744073709551615 140491965132800 140491969440152 140735769845808 140491881702984 140491967808551 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) 202052

[startup+4.40025 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19959
/proc/meminfo: memFree=190508/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=204428 CPUtime=4.37
/proc/19953/stat : 19953 (aptitude) S 19952 19953 17863 34816 17863 4202496 20910 2205 0 0 429 8 0 0 20 0 2 0 28202999 209334272 18440 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769837568 140491933877835 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 51107 18440 5110 1052 0 31698 0
[pid=19953/tid=19958] ppid=19952 vsize=204428 CPUtime=3.19
/proc/19953/task/19958/stat : 19958 (aptitude) R 19952 19953 17863 34816 17863 4202560 10182 2205 0 0 317 2 0 0 20 0 2 0 28203028 209334272 18440 18446744073709551615 140491965132800 140491969440152 140735769845808 140491881702984 140491967826301 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) 204428

[startup+4.80025 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19959
/proc/meminfo: memFree=190508/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=206988 CPUtime=4.75
/proc/19953/stat : 19953 (aptitude) R 19952 19953 17863 34816 17863 4202496 23339 2205 0 0 465 10 0 0 20 0 2 0 28202999 211955712 19263 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769838008 140491967336868 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 51747 19263 5159 1052 0 32331 0
[pid=19953/tid=19958] ppid=19952 vsize=206988 CPUtime=3.36
/proc/19953/task/19958/stat : 19958 (aptitude) S 19952 19953 17863 34816 17863 4202560 10830 2205 0 0 333 3 0 0 20 0 2 0 28203028 211955712 19263 18446744073709551615 140491965132800 140491969440152 140735769845808 140491881711616 140491933876948 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.75
Current children cumulated vsize (KiB) 206988

[startup+4.90024 s]
/proc/loadavg: 0.99 0.74 0.35 2/57 19959
/proc/meminfo: memFree=190508/1022884 swapFree=0/0
[pid=19953] ppid=19952 vsize=206988 CPUtime=4.85
/proc/19953/stat : 19953 (aptitude) R 19952 19953 17863 34816 17863 4202496 30369 2703 0 0 472 12 1 0 20 0 2 0 28202999 211955712 19263 18446744073709551615 140491965132800 140491969440152 140735769845808 140735769837784 140491922624177 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/19953/statm: 51747 19263 5159 1052 0 32331 0
[pid=19953/tid=19958] ppid=19952 vsize=206988 CPUtime=3.37
/proc/19953/task/19958/stat : 19958 (aptitude) S 19952 19953 17863 34816 17863 4202560 10830 2703 0 0 333 3 1 0 20 0 2 0 28203028 211955712 19263 18446744073709551615 140491965132800 140491969440152 140735769845808 140491881711616 140491933876948 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.85
Current children cumulated vsize (KiB) 206988

Child status: 0
Real time (s): 4.97208
CPU time (s): 4.94431
CPU user time (s): 4.7843
CPU system time (s): 0.16001
CPU usage (%): 99.4416
Max. virtual memory (cumulated for all children) (KiB): 206988

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.7843
system time used= 0.16001
maximum resident set size= 77588
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 36535
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= 71
involuntary context switches= 134

runsolver used 0.004 second user time and 0.024001 second system time

The end