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/79.runsolver.aptitude aptitude -s -y --without-recommends install avrp elib libzip-ocaml liblip1 imaze-sounds 

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.14 1.08 1.06 2/55 26155
/proc/meminfo: memFree=960224/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=3152 CPUtime=0
/proc/26155/stat : 26155 (runsolver) D 26154 26155 17863 34816 17863 4202560 77 0 0 0 0 0 0 0 20 0 1 0 29730910 3227648 99 18446744073709551615 134512640 134586868 4290676144 4290674168 4149482399 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26155/statm: 788 99 66 19 0 73 0

[startup+0.169306 s]
/proc/loadavg: 1.14 1.08 1.06 2/55 26155
/proc/meminfo: memFree=960224/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=30864 CPUtime=0
/proc/26155/stat : 26155 (aptitude) D 26154 26155 17863 34816 17863 4202496 162 0 10 0 0 0 0 0 20 0 1 0 29730910 31604736 82 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376814056 140188952429334 0 0 0 0 0 0 0 17 0 0 0 16 0 0
/proc/26155/statm: 7716 82 52 1052 0 34 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 30864

[startup+0.200407 s]
/proc/loadavg: 1.14 1.08 1.06 2/55 26155
/proc/meminfo: memFree=960224/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=36128 CPUtime=0
/proc/26155/stat : 26155 (aptitude) D 26154 26155 17863 34816 17863 4202496 172 0 11 0 0 0 0 0 20 0 1 0 29730910 36995072 92 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376813864 140188952429958 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/26155/statm: 9032 92 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.300395 s]
/proc/loadavg: 1.14 1.08 1.06 2/55 26155
/proc/meminfo: memFree=960224/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=54968 CPUtime=0
/proc/26155/stat : 26155 (aptitude) D 26154 26155 17863 34816 17863 4202496 1035 0 19 0 0 0 0 0 20 0 1 0 29730910 56287232 944 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376812600 140188923326832 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0
/proc/26155/statm: 13742 944 789 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700321 s]
/proc/loadavg: 1.14 1.08 1.06 2/55 26155
/proc/meminfo: memFree=960224/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=103288 CPUtime=0.02
/proc/26155/stat : 26155 (aptitude) D 26154 26155 17863 34816 17863 4202496 2529 1708 38 2 0 2 0 0 20 0 1 0 29730910 105766912 2368 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376808912 140188949620568 0 134217728 4096 0 0 0 0 17 0 0 0 61 0 0
/proc/26155/statm: 25822 2368 1156 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.50031 s]
/proc/loadavg: 1.14 1.08 1.06 1/56 26159
/proc/meminfo: memFree=952148/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=103288 CPUtime=0.02
/proc/26155/stat : 26155 (aptitude) D 26154 26155 17863 34816 17863 4202496 3752 1708 162 2 0 2 0 0 20 0 1 0 29730910 105766912 3715 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376808912 140188949620634 0 134217728 4096 0 0 0 0 17 0 0 0 140 0 0
/proc/26155/statm: 25822 3715 2503 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+3.10025 s]
/proc/loadavg: 1.14 1.08 1.06 1/56 26159
/proc/meminfo: memFree=949544/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=123068 CPUtime=0.52
/proc/26155/stat : 26155 (aptitude) D 26154 26155 17863 34816 17863 4202496 17368 1708 301 2 46 6 0 0 20 0 1 0 29730910 126021632 15946 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376806872 140188923326832 0 134217728 4096 0 0 0 0 17 0 0 0 251 0 0
/proc/26155/statm: 30767 15946 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.52
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30025 s]
/proc/loadavg: 1.12 1.08 1.06 2/57 26160
/proc/meminfo: memFree=802348/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=137808 CPUtime=3.06
/proc/26155/stat : 26155 (aptitude) R 26154 26155 17863 34816 17863 4202496 21686 2205 301 4 284 21 1 0 20 0 2 0 29730910 141115392 17929 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376804144 140188912066377 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 34452 17929 10303 1052 0 9789 0
[pid=26155/tid=26160] ppid=26154 vsize=137808 CPUtime=0.01
/proc/26155/task/26160/stat : 26160 (aptitude) S 26154 26155 17863 34816 17863 4202560 6 2205 0 4 0 0 1 0 20 0 2 0 29731313 141115392 17929 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842248192 140188923314900 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 137808
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.11 1.08 1.06 2/57 26161
/proc/meminfo: memFree=734396/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=273764 CPUtime=9.42
/proc/26155/stat : 26155 (aptitude) S 26154 26155 17863 34816 17863 4202496 40116 2205 301 4 906 35 1 0 20 0 2 0 29730910 280334336 35773 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376809200 140188923315787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 68441 35773 10359 1052 0 43778 0
[pid=26155/tid=26160] ppid=26154 vsize=273764 CPUtime=5.93
/proc/26155/task/26160/stat : 26160 (aptitude) R 26154 26155 17863 34816 17863 4202560 18429 2205 0 4 578 14 1 0 20 0 2 0 29731313 280334336 35773 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842241720 140188912073157 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.42
Current children cumulated vsize (KiB) 273764
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.09 1.08 1.06 2/57 26161
/proc/meminfo: memFree=650200/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=354304 CPUtime=22.16
/proc/26155/stat : 26155 (aptitude) S 26154 26155 17863 34816 17863 4202496 60810 2205 301 4 2170 45 1 0 20 0 2 0 29730910 362807296 55894 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376809200 140188923315787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 88576 55894 10360 1052 0 63913 0
[pid=26155/tid=26160] ppid=26154 vsize=354304 CPUtime=18.66
/proc/26155/task/26160/stat : 26160 (aptitude) R 26154 26155 17863 34816 17863 4202560 39123 2205 0 4 1841 24 1 0 20 0 2 0 29731313 362807296 55894 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842239512 140188956199089 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.16
Current children cumulated vsize (KiB) 354304

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

[startup+25.6004 s]
/proc/loadavg: 1.09 1.08 1.06 2/57 26161
/proc/meminfo: memFree=650200/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=354832 CPUtime=22.26
/proc/26155/stat : 26155 (aptitude) S 26154 26155 17863 34816 17863 4202496 60944 2205 301 4 2180 45 1 0 20 0 2 0 29730910 363347968 56028 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376809200 140188923315787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 88708 56028 10360 1052 0 64045 0
[pid=26155/tid=26160] ppid=26154 vsize=354832 CPUtime=18.76
/proc/26155/task/26160/stat : 26160 (aptitude) R 26154 26155 17863 34816 17863 4202560 39257 2205 0 4 1851 24 1 0 20 0 2 0 29731313 363347968 56028 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842239640 140188912081009 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) 354832

[startup+38.4002 s]
/proc/loadavg: 1.07 1.07 1.06 2/57 26161
/proc/meminfo: memFree=589936/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=418472 CPUtime=35
/proc/26155/stat : 26155 (aptitude) S 26154 26155 17863 34816 17863 4202496 76838 2205 301 4 3444 55 1 0 20 0 2 0 29730910 428515328 71904 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376809200 140188923315787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 104618 71904 10360 1052 0 79955 0
[pid=26155/tid=26160] ppid=26154 vsize=418472 CPUtime=31.5
/proc/26155/task/26160/stat : 26160 (aptitude) R 26154 26155 17863 34816 17863 4202560 55151 2205 0 4 3115 34 1 0 20 0 2 0 29731313 428515328 71904 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842239512 140188949394553 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 35
Current children cumulated vsize (KiB) 418472

[startup+44.8002 s]
/proc/loadavg: 1.06 1.07 1.06 2/57 26161
/proc/meminfo: memFree=558440/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=449548 CPUtime=41.37
/proc/26155/stat : 26155 (aptitude) S 26154 26155 17863 34816 17863 4202496 84607 2205 301 4 4076 60 1 0 20 0 2 0 29730910 460337152 79673 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376809200 140188923315787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 112387 79673 10360 1052 0 87724 0
[pid=26155/tid=26160] ppid=26154 vsize=449548 CPUtime=37.87
/proc/26155/task/26160/stat : 26160 (aptitude) R 26154 26155 17863 34816 17863 4202560 62920 2205 0 4 3747 39 1 0 20 0 2 0 29731313 460337152 79673 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842241720 140188912723155 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 41.37
Current children cumulated vsize (KiB) 449548

[startup+48.0002 s]
/proc/loadavg: 1.06 1.07 1.06 2/57 26161
/proc/meminfo: memFree=537236/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=470616 CPUtime=44.56
/proc/26155/stat : 26155 (aptitude) S 26154 26155 17863 34816 17863 4202496 89884 2205 301 4 4391 64 1 0 20 0 2 0 29730910 481910784 84949 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376809200 140188923315787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 117654 84949 10360 1052 0 92991 0
[pid=26155/tid=26160] ppid=26154 vsize=470616 CPUtime=41.06
/proc/26155/task/26160/stat : 26160 (aptitude) R 26154 26155 17863 34816 17863 4202560 68197 2205 0 4 4062 43 1 0 20 0 2 0 29731313 481910784 84949 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842242776 140188957315552 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 44.56
Current children cumulated vsize (KiB) 470616

[startup+48.8002 s]
/proc/loadavg: 1.06 1.07 1.06 2/57 26161
/proc/meminfo: memFree=530044/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=472956 CPUtime=45.35
/proc/26155/stat : 26155 (aptitude) R 26154 26155 17863 34816 17863 4202496 90703 2205 301 4 4470 64 1 0 20 0 2 0 29730910 484306944 85712 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376807576 140188912062123 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 118239 85712 10409 1052 0 93569 0
[pid=26155/tid=26160] ppid=26154 vsize=472956 CPUtime=41.41
/proc/26155/task/26160/stat : 26160 (aptitude) S 26154 26155 17863 34816 17863 4202560 68780 2205 0 4 4097 43 1 0 20 0 2 0 29731313 484306944 85712 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842248192 140188923314900 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 45.35
Current children cumulated vsize (KiB) 472956

[startup+49.2002 s]
/proc/loadavg: 1.06 1.07 1.06 2/57 26161
/proc/meminfo: memFree=530044/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=472956 CPUtime=45.75
/proc/26155/stat : 26155 (aptitude) R 26154 26155 17863 34816 17863 4202496 92346 2205 301 4 4510 64 1 0 20 0 2 0 29730910 484306944 85713 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376805304 140188956701851 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 118239 85713 10410 1052 0 93569 0
[pid=26155/tid=26160] ppid=26154 vsize=472956 CPUtime=41.41
/proc/26155/task/26160/stat : 26160 (aptitude) S 26154 26155 17863 34816 17863 4202560 68780 2205 0 4 4097 43 1 0 20 0 2 0 29731313 484306944 85713 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842248192 140188923314900 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 45.75
Current children cumulated vsize (KiB) 472956

[startup+49.6073 s]
/proc/loadavg: 1.06 1.07 1.06 2/57 26162
/proc/meminfo: memFree=529292/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=472956 CPUtime=46.15
/proc/26155/stat : 26155 (aptitude) R 26154 26155 17863 34816 17863 4202496 93651 2705 301 4 4539 74 1 1 20 0 2 0 29730910 484306944 85666 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376809256 140188950000564 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 118239 85666 10410 1052 0 93569 0
[pid=26155/tid=26160] ppid=26154 vsize=472956 CPUtime=41.42
/proc/26155/task/26160/stat : 26160 (aptitude) S 26154 26155 17863 34816 17863 4202560 68780 2705 0 4 4097 43 1 1 20 0 2 0 29731313 484306944 85666 18446744073709551615 140188954570752 140188958878104 140733376817440 140188842248192 140188923314900 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 46.15
Current children cumulated vsize (KiB) 472956

[startup+49.7005 s]
/proc/loadavg: 1.06 1.07 1.06 2/57 26162
/proc/meminfo: memFree=529292/1022884 swapFree=0/0
[pid=26155] ppid=26154 vsize=378428 CPUtime=46.24
/proc/26155/stat : 26155 (aptitude) R 26154 26155 17863 34816 17863 4202496 94047 2705 301 4 4541 81 1 1 20 0 1 0 29730910 387510272 33410 18446744073709551615 140188954570752 140188958878104 140733376817440 140733376814488 140188912436714 0 134217728 4096 0 0 0 0 17 0 0 0 316 0 0
/proc/26155/statm: 94607 33410 10413 1052 0 69937 0
Current children cumulated CPU time (s) 46.24
Current children cumulated vsize (KiB) 378428

Child status: 0
Real time (s): 49.7341
CPU time (s): 46.2949
CPU user time (s): 45.4348
CPU system time (s): 0.860053
CPU usage (%): 93.0848
Max. virtual memory (cumulated for all children) (KiB): 472956

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 45.4348
system time used= 0.860053
maximum resident set size= 343616
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 96862
page faults= 305
swaps= 0
block input operations= 255552
block output operations= 160
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2623
involuntary context switches= 881

runsolver used 0.104006 second user time and 0.140008 second system time

The end