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/76.runsolver.aptitude aptitude -s -y --without-recommends install python2.4-reportlab quack-el acl2-books-certs steptalk curl 

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.03 1.08 1.06 2/55 26120
/proc/meminfo: memFree=831856/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=54860 CPUtime=0
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 585 0 0 0 0 0 0 0 20 0 1 0 29713909 56176640 485 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161221128 140443330955462 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 13715 485 397 1052 0 73 0

[startup+0.18869 s]
/proc/loadavg: 1.03 1.08 1.06 2/55 26120
/proc/meminfo: memFree=831856/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=103288 CPUtime=0.17
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 11295 1710 0 0 15 2 0 0 20 0 1 0 29713909 105766912 11097 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213184 140443327940413 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 25822 11097 9885 1052 0 1159 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 103288

[startup+0.20028 s]
/proc/loadavg: 1.03 1.08 1.06 2/55 26120
/proc/meminfo: memFree=831856/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=103288 CPUtime=0.18
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 11298 1710 0 0 16 2 0 0 20 0 1 0 29713909 105766912 11100 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213184 140443328500529 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 25822 11100 9888 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300273 s]
/proc/loadavg: 1.03 1.08 1.06 2/55 26120
/proc/meminfo: memFree=831856/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=103288 CPUtime=0.28
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 11307 1710 0 0 26 2 0 0 20 0 1 0 29713909 105766912 11109 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213184 140443327941067 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 25822 11109 9897 1052 0 1159 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103288

[startup+0.7002 s]
/proc/loadavg: 1.03 1.08 1.06 2/55 26120
/proc/meminfo: memFree=831856/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=123068 CPUtime=0.68
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 17687 1710 0 0 63 5 0 0 20 0 1 0 29713909 126021632 15965 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161211352 140443327999817 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26120/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.03 1.08 1.06 2/57 26125
/proc/meminfo: memFree=811760/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=136060 CPUtime=1.48
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 20643 1710 0 0 141 7 0 0 20 0 2 0 29713909 139325440 17562 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213192 140443327783280 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 34015 17562 10207 1052 0 9352 0
[pid=26120/tid=26125] ppid=26119 vsize=136060 CPUtime=0
/proc/26120/task/26125/stat : 26125 (aptitude) S 26119 26120 17863 34816 17863 4202560 4 1710 0 0 0 0 0 0 20 0 2 0 29713987 139325440 17562 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220776960 140443301843668 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) 136060

[startup+3.10025 s]
/proc/loadavg: 1.03 1.08 1.06 2/57 26125
/proc/meminfo: memFree=801592/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=137824 CPUtime=3.07
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 21999 2209 0 0 294 13 0 0 20 0 2 0 29713909 141131776 17937 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161208624 140443290599787 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 34456 17937 10303 1052 0 9793 0
[pid=26120/tid=26125] ppid=26119 vsize=137824 CPUtime=0
/proc/26120/task/26125/stat : 26125 (aptitude) S 26119 26120 17863 34816 17863 4202560 6 2209 0 0 0 0 0 0 20 0 2 0 29713987 141131776 17937 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220776960 140443301843668 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) 137824

[startup+6.30024 s]
/proc/loadavg: 1.03 1.08 1.06 2/57 26126
/proc/meminfo: memFree=759928/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=250900 CPUtime=6.25
/proc/26120/stat : 26120 (aptitude) S 26119 26120 17863 34816 17863 4202496 34688 2209 0 0 608 17 0 0 20 0 2 0 29713909 256921600 30075 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213680 140443301844555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 62725 30075 10359 1052 0 38062 0
[pid=26120/tid=26125] ppid=26119 vsize=250900 CPUtime=2.82
/proc/26120/task/26125/stat : 26125 (aptitude) R 26119 26120 17863 34816 17863 4202560 12688 2209 0 0 279 3 0 0 20 0 2 0 29713987 256921600 30075 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220770488 140443335807528 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) 250900

[startup+12.7002 s]
/proc/loadavg: 1.03 1.08 1.06 2/57 26126
/proc/meminfo: memFree=712188/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=294896 CPUtime=12.62
/proc/26120/stat : 26120 (aptitude) S 26119 26120 17863 34816 17863 4202496 46067 2209 0 0 1238 24 0 0 20 0 2 0 29713909 301973504 41025 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213680 140443301844555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 73724 41025 10360 1052 0 49061 0
[pid=26120/tid=26125] ppid=26119 vsize=294896 CPUtime=9.2
/proc/26120/task/26125/stat : 26125 (aptitude) R 26119 26120 17863 34816 17863 4202560 24067 2209 0 0 910 10 0 0 20 0 2 0 29713987 301973504 41025 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220768328 140443299413893 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) 294896

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

[startup+12.8003 s]
/proc/loadavg: 1.03 1.08 1.06 2/57 26126
/proc/meminfo: memFree=712188/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=295556 CPUtime=12.72
/proc/26120/stat : 26120 (aptitude) S 26119 26120 17863 34816 17863 4202496 46242 2209 0 0 1248 24 0 0 20 0 2 0 29713909 302649344 41200 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213680 140443301844555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 73889 41200 10360 1052 0 49226 0
[pid=26120/tid=26125] ppid=26119 vsize=295556 CPUtime=9.3
/proc/26120/task/26125/stat : 26125 (aptitude) R 26119 26120 17863 34816 17863 4202560 24242 2209 0 0 920 10 0 0 20 0 2 0 29713987 302649344 41200 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220768280 140443327923321 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.72
Current children cumulated vsize (KiB) 295556

[startup+19.2002 s]
/proc/loadavg: 1.02 1.08 1.06 2/57 26126
/proc/meminfo: memFree=667300/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=337584 CPUtime=19.09
/proc/26120/stat : 26120 (aptitude) S 26119 26120 17863 34816 17863 4202496 56895 2209 0 0 1877 32 0 0 20 0 2 0 29713909 345686016 51703 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213680 140443301844555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 84396 51703 10360 1052 0 59733 0
[pid=26120/tid=26125] ppid=26119 vsize=337584 CPUtime=15.67
/proc/26120/task/26125/stat : 26125 (aptitude) R 26119 26120 17863 34816 17863 4202560 34895 2209 0 0 1548 19 0 0 20 0 2 0 29713987 345686016 51703 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220768280 140443328499417 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 19.09
Current children cumulated vsize (KiB) 337584

[startup+22.4002 s]
/proc/loadavg: 1.02 1.08 1.06 2/57 26126
/proc/meminfo: memFree=651800/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=352648 CPUtime=22.28
/proc/26120/stat : 26120 (aptitude) S 26119 26120 17863 34816 17863 4202496 60703 2209 0 0 2194 34 0 0 20 0 2 0 29713909 361111552 55486 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213680 140443301844555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 88162 55486 10360 1052 0 63499 0
[pid=26120/tid=26125] ppid=26119 vsize=352648 CPUtime=18.84
/proc/26120/task/26125/stat : 26125 (aptitude) R 26119 26120 17863 34816 17863 4202560 38703 2209 0 0 1864 20 0 0 20 0 2 0 29713987 361111552 55486 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220768280 140443328499575 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) 352648

[startup+23.2033 s]
/proc/loadavg: 1.02 1.08 1.06 2/57 26126
/proc/meminfo: memFree=647832/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=355684 CPUtime=23.07
/proc/26120/stat : 26120 (aptitude) S 26119 26120 17863 34816 17863 4202496 61448 2209 0 0 2273 34 0 0 20 0 2 0 29713909 364220416 56231 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213680 140443301844555 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 88921 56231 10360 1052 0 64258 0
[pid=26120/tid=26125] ppid=26119 vsize=355684 CPUtime=19.65
/proc/26120/task/26125/stat : 26125 (aptitude) R 26119 26120 17863 34816 17863 4202560 39448 2209 0 0 1944 21 0 0 20 0 2 0 29713987 364220416 56231 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220770488 140443335835258 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.07
Current children cumulated vsize (KiB) 355684

[startup+24.0002 s]
/proc/loadavg: 1.02 1.08 1.06 2/57 26126
/proc/meminfo: memFree=647832/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=356536 CPUtime=23.87
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 64570 2209 0 0 2351 36 0 0 20 0 2 0 29713909 365092864 56689 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161213624 140443327992144 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 89134 56689 10410 1052 0 64464 0
[pid=26120/tid=26125] ppid=26119 vsize=356536 CPUtime=19.76
/proc/26120/task/26125/stat : 26125 (aptitude) S 26119 26120 17863 34816 17863 4202560 39677 2209 0 0 1955 21 0 0 20 0 2 0 29713987 365092864 56689 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220776960 140443301843668 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.87
Current children cumulated vsize (KiB) 356536

[startup+24.2003 s]
/proc/loadavg: 1.02 1.07 1.06 2/57 26127
/proc/meminfo: memFree=644856/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=356536 CPUtime=24.07
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 64855 2709 0 0 2365 41 0 1 20 0 2 0 29713909 365092864 56827 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161212008 140443290943557 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 89134 56827 10410 1052 0 64464 0
[pid=26120/tid=26125] ppid=26119 vsize=356536 CPUtime=19.77
/proc/26120/task/26125/stat : 26125 (aptitude) S 26119 26120 17863 34816 17863 4202560 39677 2709 0 0 1955 21 0 1 20 0 2 0 29713987 365092864 56827 18446744073709551615 140443333099520 140443337406872 140734161221920 140443220776960 140443301843668 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 24.07
Current children cumulated vsize (KiB) 356536

[startup+24.3037 s]
/proc/loadavg: 1.02 1.07 1.06 2/57 26127
/proc/meminfo: memFree=644856/1022884 swapFree=0/0
[pid=26120] ppid=26119 vsize=234460 CPUtime=24.17
/proc/26120/stat : 26120 (aptitude) R 26119 26120 17863 34816 17863 4202496 65300 2709 0 0 2368 48 0 1 20 0 1 0 29713909 240087040 17868 18446744073709551615 140443333099520 140443337406872 140734161221920 140734161219032 140443290980631 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26120/statm: 58615 17868 2221 1052 0 33945 0
Current children cumulated CPU time (s) 24.17
Current children cumulated vsize (KiB) 234460

Child status: 0
Real time (s): 24.3228
CPU time (s): 24.2135
CPU user time (s): 23.6895
CPU system time (s): 0.524032
CPU usage (%): 99.5507
Max. virtual memory (cumulated for all children) (KiB): 356536

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.6895
system time used= 0.524032
maximum resident set size= 227372
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 68115
page faults= 0
swaps= 0
block input operations= 0
block output operations= 152
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 102
involuntary context switches= 469

runsolver used 0.016001 second user time and 0.100006 second system time

The end