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/18.runsolver.aptitude aptitude -s -y --without-recommends install gettext xstow freewnn-kserver holotz-castle-milanb tetrinet-client 

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.18 1.11 1.04 2/55 25131
/proc/meminfo: memFree=833364/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=3152 CPUtime=0
/proc/25131/stat : 25131 (runsolver) R 25130 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29350910 3227648 33 18446744073709551615 134512640 134586868 4289220896 4289218944 4151497776 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.17894 s]
/proc/loadavg: 1.18 1.11 1.04 2/55 25131
/proc/meminfo: memFree=833364/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=103288 CPUtime=0.16
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 11297 1707 0 0 15 1 0 0 20 0 1 0 29350910 105766912 11096 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050288 139974055098862 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 25822 11096 9884 1052 0 1159 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 103288

[startup+0.200288 s]
/proc/loadavg: 1.18 1.11 1.04 2/55 25131
/proc/meminfo: memFree=833364/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=103288 CPUtime=0.18
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 11302 1707 0 0 17 1 0 0 20 0 1 0 29350910 105766912 11101 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050288 139974055101098 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 25822 11101 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300332 s]
/proc/loadavg: 1.18 1.11 1.04 2/55 25131
/proc/meminfo: memFree=833364/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=103432 CPUtime=0.28
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 11429 1707 0 0 27 1 0 0 20 0 1 0 29350910 105914368 11220 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314048800 139974055110626 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700195 s]
/proc/loadavg: 1.18 1.11 1.04 2/55 25131
/proc/meminfo: memFree=833364/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=123068 CPUtime=0.68
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 17690 1707 0 0 62 6 0 0 20 0 1 0 29350910 126021632 15965 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314048456 139974017797663 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.5003 s]
/proc/loadavg: 1.17 1.11 1.04 2/57 25136
/proc/meminfo: memFree=813392/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=136044 CPUtime=1.48
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 20640 1707 0 0 142 6 0 0 20 0 2 0 29350910 139309056 17558 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050296 139974062508790 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 34011 17558 10207 1052 0 9348 0
[pid=25131/tid=25136] ppid=25130 vsize=136044 CPUtime=0
/proc/25131/task/25136/stat : 25136 (aptitude) S 25130 25131 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 29350987 139309056 17558 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947934720 139974029001428 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) 136044

[startup+3.10031 s]
/proc/loadavg: 1.17 1.11 1.04 2/57 25136
/proc/meminfo: memFree=803100/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=137800 CPUtime=3.07
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 21983 2205 0 0 296 11 0 0 20 0 2 0 29350910 141107200 17928 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314045728 139974017767576 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 34450 17928 10303 1052 0 9787 0
[pid=25131/tid=25136] ppid=25130 vsize=137800 CPUtime=0
/proc/25131/task/25136/stat : 25136 (aptitude) S 25130 25131 17863 34816 17863 4202560 6 2205 0 0 0 0 0 0 20 0 2 0 29350987 141107200 17928 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947934720 139974029001428 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) 137800

[startup+6.3003 s]
/proc/loadavg: 1.17 1.11 1.04 2/57 25137
/proc/meminfo: memFree=761188/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=185980 CPUtime=6.24
/proc/25131/stat : 25131 (aptitude) S 25130 25131 17863 34816 17863 4202496 34800 2205 0 0 608 16 0 0 20 0 2 0 29350910 190443520 30205 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050784 139974029002315 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 46495 30205 10359 1052 0 21832 0
[pid=25131/tid=25136] ppid=25130 vsize=185980 CPUtime=2.85
/proc/25131/task/25136/stat : 25136 (aptitude) R 25130 25131 17863 34816 17863 4202560 12817 2205 0 0 279 6 0 0 20 0 2 0 29350987 190443520 30205 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947926088 139974017759169 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 185980

[startup+12.7003 s]
/proc/loadavg: 1.14 1.11 1.03 2/57 25137
/proc/meminfo: memFree=712952/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=297056 CPUtime=12.61
/proc/25131/stat : 25131 (aptitude) S 25130 25131 17863 34816 17863 4202496 46375 2205 0 0 1241 20 0 0 20 0 2 0 29350910 304185344 41594 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050784 139974029002315 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 74264 41594 10360 1052 0 49601 0
[pid=25131/tid=25136] ppid=25130 vsize=297056 CPUtime=9.22
/proc/25131/task/25136/stat : 25136 (aptitude) R 25130 25131 17863 34816 17863 4202560 24391 2205 0 0 912 10 0 0 20 0 2 0 29350987 304185344 41594 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947927648 139974061024626 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 297056

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

[startup+12.8004 s]
/proc/loadavg: 1.14 1.11 1.03 2/57 25137
/proc/meminfo: memFree=712952/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=298376 CPUtime=12.71
/proc/25131/stat : 25131 (aptitude) S 25130 25131 17863 34816 17863 4202496 46902 2205 0 0 1251 20 0 0 20 0 2 0 29350910 305537024 41912 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050784 139974029002315 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 74594 41912 10360 1052 0 49931 0
[pid=25131/tid=25136] ppid=25130 vsize=298376 CPUtime=9.32
/proc/25131/task/25136/stat : 25136 (aptitude) R 25130 25131 17863 34816 17863 4202560 24918 2205 0 0 922 10 0 0 20 0 2 0 29350987 305537024 41912 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947926056 139974061885617 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.71
Current children cumulated vsize (KiB) 298376

[startup+19.2003 s]
/proc/loadavg: 1.13 1.10 1.03 2/57 25137
/proc/meminfo: memFree=665088/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=341776 CPUtime=19.08
/proc/25131/stat : 25131 (aptitude) S 25130 25131 17863 34816 17863 4202496 57803 2205 0 0 1886 22 0 0 20 0 2 0 29350910 349978624 52780 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050784 139974029002315 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 85444 52780 10360 1052 0 60781 0
[pid=25131/tid=25136] ppid=25130 vsize=341776 CPUtime=15.68
/proc/25131/task/25136/stat : 25136 (aptitude) R 25130 25131 17863 34816 17863 4202560 35819 2205 0 0 1556 12 0 0 20 0 2 0 29350987 349978624 52780 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947928152 139974060851520 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.08
Current children cumulated vsize (KiB) 341776

[startup+20.8003 s]
/proc/loadavg: 1.13 1.10 1.03 2/57 25137
/proc/meminfo: memFree=657896/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=352320 CPUtime=20.68
/proc/25131/stat : 25131 (aptitude) S 25130 25131 17863 34816 17863 4202496 60450 2205 0 0 2045 23 0 0 20 0 2 0 29350910 360775680 55404 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050784 139974029002315 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 88080 55404 10360 1052 0 63417 0
[pid=25131/tid=25136] ppid=25130 vsize=352320 CPUtime=17.27
/proc/25131/task/25136/stat : 25136 (aptitude) R 25130 25131 17863 34816 17863 4202560 38466 2205 0 0 1715 12 0 0 20 0 2 0 29350987 360775680 55404 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947926168 139974017767560 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 20.68
Current children cumulated vsize (KiB) 352320

[startup+21.6003 s]
/proc/loadavg: 1.12 1.10 1.03 2/57 25137
/proc/meminfo: memFree=652068/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=355948 CPUtime=21.47
/proc/25131/stat : 25131 (aptitude) S 25130 25131 17863 34816 17863 4202496 61367 2205 0 0 2124 23 0 0 20 0 2 0 29350910 364490752 56321 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050784 139974029002315 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 88987 56321 10360 1052 0 64324 0
[pid=25131/tid=25136] ppid=25130 vsize=355948 CPUtime=18.06
/proc/25131/task/25136/stat : 25136 (aptitude) R 25130 25131 17863 34816 17863 4202560 39383 2205 0 0 1794 12 0 0 20 0 2 0 29350987 364490752 56321 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947928248 139974017767560 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 21.47
Current children cumulated vsize (KiB) 355948

[startup+22.4003 s]
/proc/loadavg: 1.12 1.10 1.03 2/57 25137
/proc/meminfo: memFree=646860/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=357196 CPUtime=22.26
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 62721 2205 0 0 2202 24 0 0 20 0 2 0 29350910 365768704 56802 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314046888 139974062382638 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 89299 56802 10409 1052 0 64629 0
[pid=25131/tid=25136] ppid=25130 vsize=357196 CPUtime=18.35
/proc/25131/task/25136/stat : 25136 (aptitude) S 25130 25131 17863 34816 17863 4202560 39686 2205 0 0 1823 12 0 0 20 0 2 0 29350987 365768704 56802 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947934720 139974029001428 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.26
Current children cumulated vsize (KiB) 357196

[startup+22.8003 s]
/proc/loadavg: 1.12 1.10 1.03 2/57 25137
/proc/meminfo: memFree=646860/1022884 swapFree=0/0
[pid=25131] ppid=25130 vsize=357196 CPUtime=22.67
/proc/25131/stat : 25131 (aptitude) R 25130 25131 17863 34816 17863 4202496 64840 2704 0 0 2233 32 1 1 20 0 2 0 29350910 365768704 56994 18446744073709551615 139974060257280 139974064564632 140734314059024 140734314050840 139974018101317 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25131/statm: 89299 56994 10409 1052 0 64629 0
[pid=25131/tid=25136] ppid=25130 vsize=357196 CPUtime=18.37
/proc/25131/task/25136/stat : 25136 (aptitude) S 25130 25131 17863 34816 17863 4202560 39686 2704 0 0 1823 12 1 1 20 0 2 0 29350987 365768704 56994 18446744073709551615 139974060257280 139974064564632 140734314059024 139973947934720 139974029001428 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.67
Current children cumulated vsize (KiB) 357196

Child status: 0
Real time (s): 22.8845
CPU time (s): 22.7654
CPU user time (s): 22.3734
CPU system time (s): 0.392024
CPU usage (%): 99.4798
Max. virtual memory (cumulated for all children) (KiB): 357196

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 22.3734
system time used= 0.392024
maximum resident set size= 227976
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 68041
page faults= 0
swaps= 0
block input operations= 0
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 102
involuntary context switches= 437

runsolver used 0.052003 second user time and 0.068004 second system time

The end