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/58.runsolver.aptitude aptitude -s -y --without-recommends install libgringotts1 wmusic kdoc libmultisync-plugin-syncml tkcvs 

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.00 1.00 0.94 2/55 21584
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=3152 CPUtime=0
/proc/21584/stat : 21584 (runsolver) R 21583 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28475564 3227648 32 18446744073709551615 134512640 134586868 4293283904 4293281952 4152034352 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.179106 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21584
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=89152 CPUtime=0.16
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 7775 1709 0 0 15 1 0 0 20 0 1 0 28475564 91291648 7576 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301546816 140344565327764 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 22288 7576 6665 1052 0 858 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 89152

[startup+0.200284 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21584
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=89152 CPUtime=0.18
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 7869 1709 0 0 17 1 0 0 20 0 1 0 28475564 91291648 7662 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301545328 140344565331759 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.300267 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21584
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=101864 CPUtime=0.28
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 11708 1709 0 0 26 2 0 0 20 0 1 0 28475564 104308736 10756 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301544984 140344565383051 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.700204 s]
/proc/loadavg: 1.00 1.00 0.94 2/55 21584
/proc/meminfo: memFree=855028/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=114056 CPUtime=0.68
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 13691 1709 0 0 64 4 0 0 20 0 2 0 28475564 116793344 12063 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301546824 140344571311738 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 28514 12063 6977 1052 0 7084 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 114056

[startup+1.50024 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21589
/proc/meminfo: memFree=834436/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=115468 CPUtime=1.48
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 14566 2206 0 0 142 5 1 0 20 0 2 0 28475564 118239232 12303 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301542256 140344573058853 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 28867 12303 7073 1052 0 7437 0
[pid=21584/tid=21589] ppid=21583 vsize=115468 CPUtime=0.01
/proc/21584/task/21589/stat : 21589 (aptitude) S 21583 21584 17863 34816 17863 4202560 6 2206 0 0 0 0 1 0 20 0 2 0 28475608 118239232 12303 18446744073709551615 140344570482688 140344574790040 140734301555552 140344473888768 140344539226836 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) 115468

[startup+3.10024 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21590
/proc/meminfo: memFree=817448/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=208248 CPUtime=3.08
/proc/21584/stat : 21584 (aptitude) S 21583 21584 17863 34816 17863 4202496 22407 2206 0 0 298 9 1 0 20 0 2 0 28475564 213245952 19408 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301547312 140344539227723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 52062 19408 7129 1052 0 30632 0
[pid=21584/tid=21589] ppid=21583 vsize=208248 CPUtime=1.23
/proc/21584/task/21589/stat : 21589 (aptitude) R 21583 21584 17863 34816 17863 4202560 7827 2206 0 0 118 4 1 0 20 0 2 0 28475608 213245952 19408 18446744073709551615 140344570482688 140344574790040 140734301555552 140344473882248 140344573123760 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 208248

[startup+6.30023 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21590
/proc/meminfo: memFree=775288/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=248332 CPUtime=6.26
/proc/21584/stat : 21584 (aptitude) S 21583 21584 17863 34816 17863 4202496 32658 2206 0 0 613 12 1 0 20 0 2 0 28475564 254291968 29421 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301547312 140344539227723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 62083 29421 7129 1052 0 40653 0
[pid=21584/tid=21589] ppid=21583 vsize=248332 CPUtime=4.41
/proc/21584/task/21589/stat : 21589 (aptitude) R 21583 21584 17863 34816 17863 4202560 18078 2206 0 0 434 6 1 0 20 0 2 0 28475608 254291968 29421 18446744073709551615 140344570482688 140344574790040 140734301555552 140344473880040 140344527993209 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 248332

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

[startup+6.4003 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21590
/proc/meminfo: memFree=775288/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=248864 CPUtime=6.36
/proc/21584/stat : 21584 (aptitude) S 21583 21584 17863 34816 17863 4202496 32774 2206 0 0 623 12 1 0 20 0 2 0 28475564 254836736 29537 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301547312 140344539227723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 62216 29537 7129 1052 0 40786 0
[pid=21584/tid=21589] ppid=21583 vsize=248864 CPUtime=4.51
/proc/21584/task/21589/stat : 21589 (aptitude) R 21583 21584 17863 34816 17863 4202560 18194 2206 0 0 444 6 1 0 20 0 2 0 28475608 254836736 29537 18446744073709551615 140344570482688 140344574790040 140734301555552 140344473882296 140344573079748 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.36
Current children cumulated vsize (KiB) 248864

[startup+7.20023 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21590
/proc/meminfo: memFree=763260/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=256800 CPUtime=7.16
/proc/21584/stat : 21584 (aptitude) S 21583 21584 17863 34816 17863 4202496 34791 2206 0 0 701 14 1 0 20 0 2 0 28475564 262963200 31550 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301547312 140344539227723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 64200 31550 7130 1052 0 42770 0
[pid=21584/tid=21589] ppid=21583 vsize=256800 CPUtime=5.31
/proc/21584/task/21589/stat : 21589 (aptitude) R 21583 21584 17863 34816 17863 4202560 20211 2206 0 0 522 8 1 0 20 0 2 0 28475608 262963200 31550 18446744073709551615 140344570482688 140344574790040 140734301555552 140344473882904 140344572693594 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.16
Current children cumulated vsize (KiB) 256800

[startup+7.60023 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21590
/proc/meminfo: memFree=763260/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=259600 CPUtime=7.55
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 35798 2206 0 0 740 14 1 0 20 0 2 0 28475564 265830400 32437 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301545688 140344573084960 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 64900 32437 7178 1052 0 43463 0
[pid=21584/tid=21589] ppid=21583 vsize=259600 CPUtime=5.68
/proc/21584/task/21589/stat : 21589 (aptitude) S 21583 21584 17863 34816 17863 4202560 20889 2206 0 0 558 9 1 0 20 0 2 0 28475608 265830400 32437 18446744073709551615 140344570482688 140344574790040 140734301555552 140344473888768 140344539226836 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.55
Current children cumulated vsize (KiB) 259600

[startup+8.00024 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21590
/proc/meminfo: memFree=753216/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=259660 CPUtime=7.96
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 37723 2206 0 0 779 16 1 0 20 0 2 0 28475564 265891840 32441 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301547752 140344572686859 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 64915 32441 7179 1052 0 43478 0
[pid=21584/tid=21589] ppid=21583 vsize=259660 CPUtime=5.68
/proc/21584/task/21589/stat : 21589 (aptitude) S 21583 21584 17863 34816 17863 4202560 20889 2206 0 0 558 9 1 0 20 0 2 0 28475608 265891840 32441 18446744073709551615 140344570482688 140344574790040 140734301555552 140344473888768 140344539226836 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.96
Current children cumulated vsize (KiB) 259660

[startup+8.10023 s]
/proc/loadavg: 1.00 1.00 0.94 2/57 21590
/proc/meminfo: memFree=753216/1022884 swapFree=0/0
[pid=21584] ppid=21583 vsize=193376 CPUtime=8.06
/proc/21584/stat : 21584 (aptitude) R 21583 21584 17863 34816 17863 4202496 38412 2705 0 0 784 20 1 1 20 0 1 0 28475564 198017024 15913 18446744073709551615 140344570482688 140344574790040 140734301555552 140734301552584 140344543801653 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21584/statm: 48344 15913 1506 1052 0 32600 0
Current children cumulated CPU time (s) 8.06
Current children cumulated vsize (KiB) 193376

Child status: 0
Real time (s): 8.12652
CPU time (s): 8.0885
CPU user time (s): 7.85649
CPU system time (s): 0.232014
CPU usage (%): 99.5322
Max. virtual memory (cumulated for all children) (KiB): 259660

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.85649
system time used= 0.232014
maximum resident set size= 130188
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 41190
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= 77
involuntary context switches= 191

runsolver used 0.040002 second user time and 0 second system time

The end