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/logs/41.runsolver.aptitude aptitude -s -y --without-recommends install gnus mknbi libgdome2-0 libfilehandle-unget-perl libxkbsel-dev 

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.09 1.06 1.01 2/55 23273
/proc/meminfo: memFree=869544/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=3152 CPUtime=0
/proc/23273/stat : 23273 (runsolver) R 23272 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28885309 3227648 32 18446744073709551615 134512640 134586868 4294073648 4294071696 4151682096 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.187344 s]
/proc/loadavg: 1.09 1.06 1.01 2/55 23273
/proc/meminfo: memFree=869544/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=100508 CPUtime=0.17
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 10602 1709 0 0 14 3 0 0 20 0 1 0 28885309 102920192 10404 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644056336 140664864229109 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 25127 10404 9229 1052 0 1122 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 100508

[startup+0.200282 s]
/proc/loadavg: 1.09 1.06 1.01 2/55 23273
/proc/meminfo: memFree=869544/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=100508 CPUtime=0.18
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 10605 1709 0 0 15 3 0 0 20 0 1 0 28885309 102920192 10407 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644056336 140664864228840 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 25127 10407 9232 1052 0 1122 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 100508

[startup+0.300324 s]
/proc/loadavg: 1.09 1.06 1.01 2/55 23273
/proc/meminfo: memFree=869544/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=104484 CPUtime=0.28
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 11183 1709 0 0 25 3 0 0 20 0 1 0 28885309 106991616 10977 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644056728 140664871536733 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 26121 10977 9300 1052 0 2116 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 104484

[startup+0.70021 s]
/proc/loadavg: 1.09 1.06 1.01 2/55 23273
/proc/meminfo: memFree=869544/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=123288 CPUtime=0.68
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 17028 1709 0 0 62 6 0 0 20 0 2 0 28885309 126246912 14303 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644060856 140664826575527 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 123288

[startup+1.50024 s]
/proc/loadavg: 1.09 1.06 1.01 2/57 23278
/proc/meminfo: memFree=841264/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=132388 CPUtime=1.48
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 19434 1709 0 0 141 7 0 0 20 0 2 0 28885309 135565312 16704 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644055424 140664826898759 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 33097 16704 9585 1052 0 9092 0
[pid=23273/tid=23278] ppid=23272 vsize=132388 CPUtime=0
/proc/23273/task/23278/stat : 23278 (aptitude) S 23272 23273 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 28885375 135565312 16704 18446744073709551615 140664869388288 140664873695640 140733644065072 140664760215552 140664838132436 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) 132388

[startup+3.10031 s]
/proc/loadavg: 1.09 1.06 1.01 2/57 23279
/proc/meminfo: memFree=840016/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=133892 CPUtime=3.07
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 20601 2208 0 0 294 13 0 0 20 0 2 0 28885309 137105408 16941 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644051888 140664864216108 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 33473 16941 9644 1052 0 9468 0
[pid=23273/tid=23278] ppid=23272 vsize=133892 CPUtime=0
/proc/23273/task/23278/stat : 23278 (aptitude) S 23272 23273 17863 34816 17863 4202560 6 2208 0 0 0 0 0 0 20 0 2 0 28885375 137105408 16941 18446744073709551615 140664869388288 140664873695640 140733644065072 140664760215552 140664838132436 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) 133892

[startup+6.30024 s]
/proc/loadavg: 1.08 1.06 1.01 2/57 23279
/proc/meminfo: memFree=797120/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=179444 CPUtime=6.25
/proc/23273/stat : 23273 (aptitude) S 23272 23273 17863 34816 17863 4202496 33025 2208 0 0 608 17 0 0 20 0 2 0 28885309 183750656 28589 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644056832 140664838133323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 44861 28589 9700 1052 0 20856 0
[pid=23273/tid=23278] ppid=23272 vsize=179444 CPUtime=3.14
/proc/23273/task/23278/stat : 23278 (aptitude) R 23272 23273 17863 34816 17863 4202560 12424 2208 0 0 310 4 0 0 20 0 2 0 28885375 183750656 28589 18446744073709551615 140664869388288 140664873695640 140733644065072 140664760206872 140664826898759 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 179444

[startup+12.7003 s]
/proc/loadavg: 1.08 1.06 1.01 2/57 23279
/proc/meminfo: memFree=742436/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=300680 CPUtime=12.62
/proc/23273/stat : 23273 (aptitude) S 23272 23273 17863 34816 17863 4202496 47228 2208 0 0 1240 22 0 0 20 0 2 0 28885309 307896320 42484 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644056832 140664838133323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 75170 42484 9700 1052 0 51165 0
[pid=23273/tid=23278] ppid=23272 vsize=300680 CPUtime=9.5
/proc/23273/task/23278/stat : 23278 (aptitude) R 23272 23273 17863 34816 17863 4202560 26626 2208 0 0 941 9 0 0 20 0 2 0 28885375 307896320 42484 18446744073709551615 140664869388288 140664873695640 140733644065072 140664760208984 140664827540768 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.62
Current children cumulated vsize (KiB) 300680

[startup+25.5003 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23279
/proc/meminfo: memFree=655140/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=382600 CPUtime=25.35
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 67929 2208 0 0 2503 32 0 0 20 0 2 0 28885309 391782400 63122 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644055208 140664826879550 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 95650 63122 9750 1052 0 71638 0
[pid=23273/tid=23278] ppid=23272 vsize=382600 CPUtime=21.95
/proc/23273/task/23278/stat : 23278 (aptitude) S 23272 23273 17863 34816 17863 4202560 47094 2208 0 0 2176 19 0 0 20 0 2 0 28885375 391782400 63122 18446744073709551615 140664869388288 140664873695640 140733644065072 140664760215552 140664838132436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.35
Current children cumulated vsize (KiB) 382600

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

[startup+25.6004 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23279
/proc/meminfo: memFree=655140/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=382600 CPUtime=25.45
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 67929 2208 0 0 2513 32 0 0 20 0 2 0 28885309 391782400 63122 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644055208 140664826879600 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 95650 63122 9750 1052 0 71638 0
[pid=23273/tid=23278] ppid=23272 vsize=382600 CPUtime=21.95
/proc/23273/task/23278/stat : 23278 (aptitude) S 23272 23273 17863 34816 17863 4202560 47094 2208 0 0 2176 19 0 0 20 0 2 0 28885375 391782400 63122 18446744073709551615 140664869388288 140664873695640 140733644065072 140664760215552 140664838132436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.45
Current children cumulated vsize (KiB) 382600

[startup+26.0003 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23279
/proc/meminfo: memFree=655140/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=382600 CPUtime=25.86
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 70503 2707 0 0 2548 37 0 1 20 0 2 0 28885309 391782400 63173 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644055784 140664835694650 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 95650 63173 9751 1052 0 71638 0
[pid=23273/tid=23278] ppid=23272 vsize=382600 CPUtime=21.96
/proc/23273/task/23278/stat : 23278 (aptitude) S 23272 23273 17863 34816 17863 4202560 47094 2707 0 0 2176 19 0 1 20 0 2 0 28885375 391782400 63173 18446744073709551615 140664869388288 140664873695640 140733644065072 140664760215552 140664838132436 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.86
Current children cumulated vsize (KiB) 382600

[startup+26.2012 s]
/proc/loadavg: 1.06 1.05 1.01 2/57 23279
/proc/meminfo: memFree=655140/1022884 swapFree=0/0
[pid=23273] ppid=23272 vsize=189108 CPUtime=26.06
/proc/23273/stat : 23273 (aptitude) R 23272 23273 17863 34816 17863 4202496 71200 2707 0 0 2558 47 0 1 20 0 1 0 28885309 193646592 6550 18446744073709551615 140664869388288 140664873695640 140733644065072 140733644064632 140664827254250 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/23273/statm: 47277 6550 1509 1052 0 31533 0
Current children cumulated CPU time (s) 26.06
Current children cumulated vsize (KiB) 189108

Child status: 0
Real time (s): 26.2065
CPU time (s): 26.0896
CPU user time (s): 25.5936
CPU system time (s): 0.496031
CPU usage (%): 99.5539
Max. virtual memory (cumulated for all children) (KiB): 382600

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 25.5936
system time used= 0.496031
maximum resident set size= 253236
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 73974
page faults= 0
swaps= 0
block input operations= 0
block output operations= 136
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 107
involuntary context switches= 491

runsolver used 0.048003 second user time and 0.080005 second system time

The end