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/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.01 1.06 1.04 2/55 25734
/proc/meminfo: memFree=830188/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=3152 CPUtime=0
/proc/25734/stat : 25734 (runsolver) R 25733 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29604021 3227648 33 18446744073709551615 134512640 134586868 4292724608 4292722656 4151723056 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.162354 s]
/proc/loadavg: 1.01 1.06 1.04 2/55 25734
/proc/meminfo: memFree=830188/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=103288 CPUtime=0.14
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 11291 1709 0 0 13 1 0 0 20 0 1 0 29604021 105766912 11091 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573626720 140500340602772 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 25822 11091 9879 1052 0 1159 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 103288

[startup+0.200277 s]
/proc/loadavg: 1.01 1.06 1.04 2/55 25734
/proc/meminfo: memFree=830188/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=103288 CPUtime=0.19
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 11303 1709 0 0 17 2 0 0 20 0 1 0 29604021 105766912 11103 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573626720 140500341157503 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 25822 11103 9891 1052 0 1159 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 103288

[startup+0.300265 s]
/proc/loadavg: 1.01 1.06 1.04 2/55 25734
/proc/meminfo: memFree=830188/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=107392 CPUtime=0.29
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 11538 1709 0 0 27 2 0 0 20 0 1 0 29604021 109969408 11330 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627112 140500347906133 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 26848 11330 9959 1052 0 2185 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 107392

[startup+0.700204 s]
/proc/loadavg: 1.01 1.06 1.04 2/55 25734
/proc/meminfo: memFree=830188/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=123068 CPUtime=0.68
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 17689 1709 0 0 62 6 0 0 20 0 1 0 29604021 126021632 15965 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573624888 140500303298027 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.01 1.06 1.04 2/57 25739
/proc/meminfo: memFree=810216/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=136044 CPUtime=1.48
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 20641 1709 0 0 140 8 0 0 20 0 2 0 29604021 139309056 17559 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573626728 140500312073617 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 34011 17559 10207 1052 0 9348 0
[pid=25734/tid=25739] ppid=25733 vsize=136044 CPUtime=0
/proc/25734/task/25739/stat : 25739 (aptitude) S 25733 25734 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29604096 139309056 17559 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233435136 140500314501844 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.10025 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25739
/proc/meminfo: memFree=800048/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=137800 CPUtime=3.08
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 21985 2207 0 0 294 13 1 0 20 0 2 0 29604021 141107200 17930 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573622160 140500348726852 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 34450 17930 10303 1052 0 9787 0
[pid=25734/tid=25739] ppid=25733 vsize=137800 CPUtime=0.01
/proc/25734/task/25739/stat : 25739 (aptitude) S 25733 25734 17863 34816 17863 4202560 6 2207 0 0 0 0 1 0 20 0 2 0 29604096 141107200 17930 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233435136 140500314501844 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) 137800

[startup+6.30024 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=757764/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=186124 CPUtime=6.26
/proc/25734/stat : 25734 (aptitude) S 25733 25734 17863 34816 17863 4202496 34826 2207 0 0 607 18 1 0 20 0 2 0 29604021 190590976 30236 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627216 140500314502731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 46531 30236 10359 1052 0 21868 0
[pid=25734/tid=25739] ppid=25733 vsize=186124 CPUtime=2.88
/proc/25734/task/25739/stat : 25739 (aptitude) R 25733 25734 17863 34816 17863 4202560 12841 2207 0 0 283 4 1 0 20 0 2 0 29604096 190590976 30236 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233428664 140500348472665 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) 186124

[startup+12.7002 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=710272/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=296824 CPUtime=12.64
/proc/25734/stat : 25734 (aptitude) S 25733 25734 17863 34816 17863 4202496 46519 2207 0 0 1239 24 1 0 20 0 2 0 29604021 303947776 41528 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627216 140500314502731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 74206 41528 10360 1052 0 49543 0
[pid=25734/tid=25739] ppid=25733 vsize=296824 CPUtime=9.25
/proc/25734/task/25739/stat : 25739 (aptitude) R 25733 25734 17863 34816 17863 4202560 24533 2207 0 0 914 10 1 0 20 0 2 0 29604096 303947776 41528 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233426456 140500340581497 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 296824

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

[startup+12.8003 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=710272/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=297352 CPUtime=12.74
/proc/25734/stat : 25734 (aptitude) S 25733 25734 17863 34816 17863 4202496 46642 2207 0 0 1249 24 1 0 20 0 2 0 29604021 304488448 41651 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627216 140500314502731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 74338 41651 10360 1052 0 49675 0
[pid=25734/tid=25739] ppid=25733 vsize=297352 CPUtime=9.35
/proc/25734/task/25739/stat : 25739 (aptitude) R 25733 25734 17863 34816 17863 4202560 24656 2207 0 0 924 10 1 0 20 0 2 0 29604096 304488448 41651 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233426456 140500348586588 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.74
Current children cumulated vsize (KiB) 297352

[startup+19.2002 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=667120/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=336460 CPUtime=19.1
/proc/25734/stat : 25734 (aptitude) S 25733 25734 17863 34816 17863 4202496 56448 2207 0 0 1883 26 1 0 20 0 2 0 29604021 344535040 51431 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627216 140500314502731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 84115 51431 10360 1052 0 59452 0
[pid=25734/tid=25739] ppid=25733 vsize=336460 CPUtime=15.72
/proc/25734/task/25739/stat : 25739 (aptitude) R 25733 25734 17863 34816 17863 4202560 34462 2207 0 0 1558 13 1 0 20 0 2 0 29604096 344535040 51431 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233428664 140500347386033 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.1
Current children cumulated vsize (KiB) 336460

[startup+20.8002 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=662408/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=345436 CPUtime=20.7
/proc/25734/stat : 25734 (aptitude) S 25733 25734 17863 34816 17863 4202496 58739 2207 0 0 2040 29 1 0 20 0 2 0 29604021 353726464 53694 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627216 140500314502731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 86359 53694 10360 1052 0 61696 0
[pid=25734/tid=25739] ppid=25733 vsize=345436 CPUtime=17.32
/proc/25734/task/25739/stat : 25739 (aptitude) R 25733 25734 17863 34816 17863 4202560 36753 2207 0 0 1716 15 1 0 20 0 2 0 29604096 353726464 53694 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233426584 140500348648851 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 20.7
Current children cumulated vsize (KiB) 345436

[startup+22.4002 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=651000/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=352172 CPUtime=22.28
/proc/25734/stat : 25734 (aptitude) S 25733 25734 17863 34816 17863 4202496 60402 2207 0 0 2198 29 1 0 20 0 2 0 29604021 360624128 55357 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627216 140500314502731 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 88043 55357 10361 1052 0 63380 0
[pid=25734/tid=25739] ppid=25733 vsize=352172 CPUtime=18.91
/proc/25734/task/25739/stat : 25739 (aptitude) R 25733 25734 17863 34816 17863 4202560 38416 2207 0 0 1874 16 1 0 20 0 2 0 29604096 360624128 55357 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233426456 140500346586784 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.28
Current children cumulated vsize (KiB) 352172

[startup+23.2032 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=647032/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=353972 CPUtime=23.09
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 61099 2207 0 0 2278 30 1 0 20 0 2 0 29604021 362467328 55999 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573625592 140500303249024 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 88493 55999 10409 1052 0 63823 0
[pid=25734/tid=25739] ppid=25733 vsize=353972 CPUtime=19.31
/proc/25734/task/25739/stat : 25739 (aptitude) S 25733 25734 17863 34816 17863 4202560 38883 2207 0 0 1914 16 1 0 20 0 2 0 29604096 362467328 55999 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233435136 140500314501844 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.09
Current children cumulated vsize (KiB) 353972

[startup+23.6002 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=647032/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=353972 CPUtime=23.48
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 63887 2706 0 0 2311 35 1 1 20 0 2 0 29604021 362467328 56085 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573626616 140500312066204 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 88493 56085 10410 1052 0 63823 0
[pid=25734/tid=25739] ppid=25733 vsize=353972 CPUtime=19.32
/proc/25734/task/25739/stat : 25739 (aptitude) S 25733 25734 17863 34816 17863 4202560 38883 2706 0 0 1914 16 1 1 20 0 2 0 29604096 362467328 56085 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233435136 140500314501844 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.48
Current children cumulated vsize (KiB) 353972

[startup+23.7002 s]
/proc/loadavg: 1.01 1.05 1.04 2/57 25740
/proc/meminfo: memFree=647032/1022884 swapFree=0/0
[pid=25734] ppid=25733 vsize=353972 CPUtime=23.58
/proc/25734/stat : 25734 (aptitude) R 25733 25734 17863 34816 17863 4202496 64047 2706 0 0 2318 38 1 1 20 0 2 0 29604021 362467328 56194 18446744073709551615 140500345757696 140500350065048 140735573635456 140735573627272 140500312070292 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25734/statm: 88493 56194 10410 1052 0 63823 0
[pid=25734/tid=25739] ppid=25733 vsize=353972 CPUtime=19.32
/proc/25734/task/25739/stat : 25739 (aptitude) S 25733 25734 17863 34816 17863 4202560 38883 2706 0 0 1914 16 1 1 20 0 2 0 29604096 362467328 56194 18446744073709551615 140500345757696 140500350065048 140735573635456 140500233435136 140500314501844 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.58
Current children cumulated vsize (KiB) 353972

Child status: 0
Real time (s): 23.7759
CPU time (s): 23.6735
CPU user time (s): 23.2215
CPU system time (s): 0.452028
CPU usage (%): 99.5692
Max. virtual memory (cumulated for all children) (KiB): 353972

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.2215
system time used= 0.452028
maximum resident set size= 224776
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67272
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= 101
involuntary context switches= 447

runsolver used 0.032002 second user time and 0.080005 second system time

The end