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/logs/50.runsolver.aptitude aptitude -s -y --without-recommends install libdebconfclient0 krec libhesiod0 python2.3-diacanvas2 kudzu 

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.07 1.03 0.94 2/55 21513
/proc/meminfo: memFree=923740/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=3152 CPUtime=0
/proc/21513/stat : 21513 (runsolver) R 21512 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28449390 3227648 32 18446744073709551615 134512640 134586868 4292392480 4292390528 4151919664 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21513/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.15366 s]
/proc/loadavg: 1.07 1.03 0.94 2/55 21513
/proc/meminfo: memFree=923740/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=12328 CPUtime=0
/proc/21513/stat : 21513 (aptitude) D 21512 21513 17863 34816 17863 4202496 127 0 7 0 0 0 0 0 20 0 1 0 28449390 12623872 50 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406300872 140161584821795 0 0 0 0 0 0 0 17 0 0 0 14 0 0
/proc/21513/statm: 3082 50 36 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.200288 s]
/proc/loadavg: 1.07 1.03 0.94 2/55 21513
/proc/meminfo: memFree=923740/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=23840 CPUtime=0
/proc/21513/stat : 21513 (aptitude) D 21512 21513 17863 34816 17863 4202496 143 0 11 0 0 0 0 0 20 0 1 0 28449390 24412160 67 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406300680 140161584821006 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/21513/statm: 5960 67 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300352 s]
/proc/loadavg: 1.07 1.03 0.94 2/55 21513
/proc/meminfo: memFree=923740/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=40832 CPUtime=0
/proc/21513/stat : 21513 (aptitude) D 21512 21513 17863 34816 17863 4202496 173 0 20 0 0 0 0 0 20 0 1 0 28449390 41811968 100 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406300392 140161584821795 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/21513/statm: 10208 100 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.700331 s]
/proc/loadavg: 1.07 1.03 0.94 2/55 21513
/proc/meminfo: memFree=923740/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=63520 CPUtime=0.01
/proc/21513/stat : 21513 (aptitude) D 21512 21513 17863 34816 17863 4202496 1228 571 48 4 1 0 0 0 20 0 1 0 28449390 65044480 1122 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406296960 140161544650597 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/21513/statm: 15880 1122 940 1052 0 143 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 63520

[startup+1.50033 s]
/proc/loadavg: 1.07 1.03 0.94 1/56 21517
/proc/meminfo: memFree=914548/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=89152 CPUtime=0.03
/proc/21513/stat : 21513 (aptitude) D 21512 21513 17863 34816 17863 4202496 2681 1705 150 4 2 0 1 0 20 0 1 0 28449390 91291648 2628 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406295440 140161582012314 0 134217728 4096 0 0 0 0 17 0 0 0 141 0 0
/proc/21513/statm: 22288 2628 1718 1052 0 858 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 89152

[startup+3.10021 s]
/proc/loadavg: 1.07 1.03 0.94 2/56 21517
/proc/meminfo: memFree=912068/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=110192 CPUtime=0.69
/proc/21513/stat : 21513 (aptitude) R 21512 21513 17863 34816 17863 4202496 12428 1705 253 4 63 5 1 0 20 0 2 0 28449390 112836608 11052 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406296008 140161544472903 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 235 0 0
/proc/21513/statm: 27548 11052 6961 1052 0 6118 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 110192
heavy processes:

[startup+6.30023 s]
/proc/loadavg: 1.06 1.03 0.94 2/57 21519
/proc/meminfo: memFree=819060/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=139000 CPUtime=3.79
/proc/21513/stat : 21513 (aptitude) S 21512 21513 17863 34816 17863 4202496 20840 2202 253 5 367 11 1 0 20 0 2 0 28449390 142336000 18454 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406295728 140161555707467 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 241 0 0
/proc/21513/statm: 34750 18454 7129 1052 0 13320 0
[pid=21513/tid=21518] ppid=21512 vsize=139000 CPUtime=1.79
/proc/21513/task/21518/stat : 21518 (aptitude) R 21512 21513 17863 34816 17863 4202560 6472 2202 0 5 174 4 1 0 20 0 2 0 28449678 142336000 18454 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490359832 140161587607858 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.79
Current children cumulated vsize (KiB) 139000
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.06 1.03 0.94 2/57 21519
/proc/meminfo: memFree=762020/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=259228 CPUtime=10.16
/proc/21513/stat : 21513 (aptitude) S 21512 21513 17863 34816 17863 4202496 34853 2202 253 5 997 18 1 0 20 0 2 0 28449390 265449472 32129 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406295728 140161555707467 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 241 0 0
/proc/21513/statm: 64807 32129 7129 1052 0 43377 0
[pid=21513/tid=21518] ppid=21512 vsize=259228 CPUtime=8.15
/proc/21513/task/21518/stat : 21518 (aptitude) R 21512 21513 17863 34816 17863 4202560 20484 2202 0 5 803 11 1 0 20 0 2 0 28449678 265449472 32129 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490359832 140161589659522 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.16
Current children cumulated vsize (KiB) 259228
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=648560/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=368796 CPUtime=22.89
/proc/21513/stat : 21513 (aptitude) S 21512 21513 17863 34816 17863 4202496 62282 2202 253 5 2262 26 1 0 20 0 2 0 28449390 377647104 59506 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406295728 140161555707467 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 241 0 0
/proc/21513/statm: 92199 59506 7129 1052 0 70769 0
[pid=21513/tid=21518] ppid=21512 vsize=368796 CPUtime=20.89
/proc/21513/task/21518/stat : 21518 (aptitude) R 21512 21513 17863 34816 17863 4202560 47913 2202 0 5 2069 19 1 0 20 0 2 0 28449678 377647104 59506 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490362040 140161588590753 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.89
Current children cumulated vsize (KiB) 368796

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

[startup+25.6003 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=648560/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=369324 CPUtime=22.99
/proc/21513/stat : 21513 (aptitude) S 21512 21513 17863 34816 17863 4202496 62405 2202 253 5 2272 26 1 0 20 0 2 0 28449390 378187776 59629 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406295728 140161555707467 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 241 0 0
/proc/21513/statm: 92331 59629 7129 1052 0 70901 0
[pid=21513/tid=21518] ppid=21512 vsize=369324 CPUtime=20.99
/proc/21513/task/21518/stat : 21518 (aptitude) R 21512 21513 17863 34816 17863 4202560 48036 2202 0 5 2079 19 1 0 20 0 2 0 28449678 378187776 59629 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490359832 140161555698019 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.99
Current children cumulated vsize (KiB) 369324

[startup+28.8002 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=633556/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=383504 CPUtime=26.18
/proc/21513/stat : 21513 (aptitude) S 21512 21513 17863 34816 17863 4202496 66155 2202 253 5 2588 29 1 0 20 0 2 0 28449390 392708096 63196 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406295728 140161555707467 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 241 0 0
/proc/21513/statm: 95876 63196 7129 1052 0 74446 0
[pid=21513/tid=21518] ppid=21512 vsize=383504 CPUtime=24.18
/proc/21513/task/21518/stat : 21518 (aptitude) R 21512 21513 17863 34816 17863 4202560 51786 2202 0 5 2395 22 1 0 20 0 2 0 28449678 392708096 63196 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490362040 140161587607858 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 26.18
Current children cumulated vsize (KiB) 383504

[startup+32.0032 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=618056/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=398608 CPUtime=29.36
/proc/21513/stat : 21513 (aptitude) S 21512 21513 17863 34816 17863 4202496 69910 2202 254 5 2905 30 1 0 20 0 2 0 28449390 408174592 66949 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406295728 140161555707467 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 241 0 0
/proc/21513/statm: 99652 66949 7130 1052 0 78222 0
[pid=21513/tid=21518] ppid=21512 vsize=398608 CPUtime=27.35
/proc/21513/task/21518/stat : 21518 (aptitude) R 21512 21513 17863 34816 17863 4202560 55541 2202 1 5 2712 22 1 0 20 0 2 0 28449678 408174592 66949 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490359784 140161589609098 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 29.36
Current children cumulated vsize (KiB) 398608

[startup+32.8002 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=618056/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=401816 CPUtime=30.09
/proc/21513/stat : 21513 (aptitude) R 21512 21513 17863 34816 17863 4202496 71070 2202 263 5 2978 30 1 0 20 0 2 0 28449390 411459584 67990 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406294104 140161544458064 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 248 0 0
/proc/21513/statm: 100454 67990 7178 1052 0 79017 0
[pid=21513/tid=21518] ppid=21512 vsize=401816 CPUtime=27.96
/proc/21513/task/21518/stat : 21518 (aptitude) S 21512 21513 17863 34816 17863 4202560 56366 2202 2 5 2773 22 1 0 20 0 2 0 28449678 411459584 67990 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490368512 140161555706580 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 30.09
Current children cumulated vsize (KiB) 401816

[startup+33.2002 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=612352/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=401904 CPUtime=30.48
/proc/21513/stat : 21513 (aptitude) R 21512 21513 17863 34816 17863 4202496 71105 2202 263 5 3017 30 1 0 20 0 2 0 28449390 411549696 68025 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406294104 140161544453750 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 248 0 0
/proc/21513/statm: 100476 68025 7178 1052 0 79039 0
[pid=21513/tid=21518] ppid=21512 vsize=401904 CPUtime=27.96
/proc/21513/task/21518/stat : 21518 (aptitude) S 21512 21513 17863 34816 17863 4202560 56366 2202 2 5 2773 22 1 0 20 0 2 0 28449678 411549696 68025 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490368512 140161555706580 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 30.48
Current children cumulated vsize (KiB) 401904

[startup+33.6002 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=612352/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=401904 CPUtime=30.88
/proc/21513/stat : 21513 (aptitude) R 21512 21513 17863 34816 17863 4202496 73085 2202 263 5 3054 33 1 0 20 0 2 0 28449390 411549696 68012 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406293728 140161544665398 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 248 0 0
/proc/21513/statm: 100476 68012 7179 1052 0 79039 0
[pid=21513/tid=21518] ppid=21512 vsize=401904 CPUtime=27.96
/proc/21513/task/21518/stat : 21518 (aptitude) S 21512 21513 17863 34816 17863 4202560 56366 2202 2 5 2773 22 1 0 20 0 2 0 28449678 411549696 68012 18446744073709551615 140161586962432 140161591269784 140736406303968 140161490368512 140161555706580 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 30.88
Current children cumulated vsize (KiB) 401904

[startup+33.7004 s]
/proc/loadavg: 1.04 1.02 0.94 2/57 21519
/proc/meminfo: memFree=612352/1022884 swapFree=0/0
[pid=21513] ppid=21512 vsize=278724 CPUtime=30.97
/proc/21513/stat : 21513 (aptitude) D 21512 21513 17863 34816 17863 4202496 73813 2702 265 5 3056 40 1 0 20 0 1 0 28449390 285413376 37221 18446744073709551615 140161586962432 140161591269784 140736406303968 140736406301000 140161560320416 0 134217728 4096 0 0 0 0 17 0 0 0 248 0 0
/proc/21513/statm: 69681 37221 1504 1052 0 53937 0
Current children cumulated CPU time (s) 30.97
Current children cumulated vsize (KiB) 278724

Child status: 0
Real time (s): 33.7769
CPU time (s): 31.0259
CPU user time (s): 30.5819
CPU system time (s): 0.444027
CPU usage (%): 91.8556
Max. virtual memory (cumulated for all children) (KiB): 401904

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 30.5819
system time used= 0.444027
maximum resident set size= 272432
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 76584
page faults= 281
swaps= 0
block input operations= 135496
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1536
involuntary context switches= 606

runsolver used 0 second user time and 0.16801 second system time

The end