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/61.runsolver.aptitude aptitude -s -y --without-recommends install prime-dict pnet-ctools bochs-x php3-cgi memcached 

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.04 1.03 2/55 25761
/proc/meminfo: memFree=829692/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=3152 CPUtime=0
/proc/25761/stat : 25761 (runsolver) R 25760 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29613642 3227648 33 18446744073709551615 134512640 134586868 4288217360 4288215408 4151305264 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.192171 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25761
/proc/meminfo: memFree=829692/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=103288 CPUtime=0.17
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 11297 1707 0 0 15 2 0 0 20 0 1 0 29613642 105766912 11099 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191156720 139970787289334 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 25822 11099 9886 1052 0 1159 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 103288

[startup+0.200296 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25761
/proc/meminfo: memFree=829692/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=103288 CPUtime=0.18
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 11300 1707 0 0 16 2 0 0 20 0 1 0 29613642 105766912 11102 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191156720 139970787288651 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 25822 11102 9889 1052 0 1159 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 103288

[startup+0.300265 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25761
/proc/meminfo: memFree=829692/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=103432 CPUtime=0.28
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 11427 1707 0 0 26 2 0 0 20 0 1 0 29613642 105914368 11221 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191155232 139970787301346 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 25858 11221 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 103432

[startup+0.700201 s]
/proc/loadavg: 1.00 1.04 1.03 2/55 25761
/proc/meminfo: memFree=829692/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=123068 CPUtime=0.68
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 17688 1707 0 0 62 6 0 0 20 0 1 0 29613642 126021632 15966 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191154888 139970749988383 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 30767 15966 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.00 1.04 1.03 2/57 25766
/proc/meminfo: memFree=809596/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=136052 CPUtime=1.48
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 20642 1707 0 0 142 6 0 0 20 0 2 0 29613642 139317248 17561 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191156728 139970750029655 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 34013 17561 10207 1052 0 9350 0
[pid=25761/tid=25766] ppid=25760 vsize=136052 CPUtime=0
/proc/25761/task/25766/stat : 25766 (aptitude) S 25760 25761 17863 34816 17863 4202560 4 1707 0 0 0 0 0 0 20 0 2 0 29613719 139317248 17561 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680125440 139970761192148 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) 136052

[startup+3.10024 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25766
/proc/meminfo: memFree=799428/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=137804 CPUtime=3.07
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 21985 2206 0 0 295 12 0 0 20 0 2 0 29613642 141111296 17930 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191152160 139970793093426 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 34451 17930 10303 1052 0 9788 0
[pid=25761/tid=25766] ppid=25760 vsize=137804 CPUtime=0
/proc/25761/task/25766/stat : 25766 (aptitude) S 25760 25761 17863 34816 17863 4202560 6 2206 0 0 0 0 0 0 20 0 2 0 29613719 141111296 17930 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680125440 139970761192148 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) 137804

[startup+6.30024 s]
/proc/loadavg: 1.00 1.04 1.03 2/57 25767
/proc/meminfo: memFree=757268/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=251672 CPUtime=6.25
/proc/25761/stat : 25761 (aptitude) S 25760 25761 17863 34816 17863 4202496 34857 2206 0 0 607 18 0 0 20 0 2 0 29613642 257712128 30246 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191157216 139970761193035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 62918 30246 10359 1052 0 38255 0
[pid=25761/tid=25766] ppid=25760 vsize=251672 CPUtime=2.87
/proc/25761/task/25766/stat : 25766 (aptitude) R 25760 25761 17863 34816 17863 4202560 12871 2206 0 0 281 6 0 0 20 0 2 0 29613719 257712128 30246 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680116808 139970794649371 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) 251672

[startup+12.7002 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=709280/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=297228 CPUtime=12.62
/proc/25761/stat : 25761 (aptitude) S 25760 25761 17863 34816 17863 4202496 46600 2206 0 0 1242 20 0 0 20 0 2 0 29613642 304361472 41610 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191157216 139970761193035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 74307 41610 10360 1052 0 49644 0
[pid=25761/tid=25766] ppid=25760 vsize=297228 CPUtime=9.24
/proc/25761/task/25766/stat : 25766 (aptitude) R 25760 25761 17863 34816 17863 4202560 24614 2206 0 0 915 9 0 0 20 0 2 0 29613719 304361472 41610 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680119144 139970749958521 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) 297228

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

[startup+12.8003 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=709280/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=297756 CPUtime=12.72
/proc/25761/stat : 25761 (aptitude) S 25760 25761 17863 34816 17863 4202496 46737 2206 0 0 1252 20 0 0 20 0 2 0 29613642 304902144 41747 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191157216 139970761193035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 74439 41747 10360 1052 0 49776 0
[pid=25761/tid=25766] ppid=25760 vsize=297756 CPUtime=9.34
/proc/25761/task/25766/stat : 25766 (aptitude) R 25760 25761 17863 34816 17863 4202560 24751 2206 0 0 925 9 0 0 20 0 2 0 29613719 304902144 41747 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680118920 139970793226872 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) 297756

[startup+19.2002 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=665632/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=337424 CPUtime=19.09
/proc/25761/stat : 25761 (aptitude) S 25760 25761 17863 34816 17863 4202496 56704 2206 0 0 1885 24 0 0 20 0 2 0 29613642 345522176 51692 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191157216 139970761193035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 84356 51692 10360 1052 0 59693 0
[pid=25761/tid=25766] ppid=25760 vsize=337424 CPUtime=15.71
/proc/25761/task/25766/stat : 25766 (aptitude) R 25760 25761 17863 34816 17863 4202560 34718 2206 0 0 1559 12 0 0 20 0 2 0 29613719 345522176 51692 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680116760 139970795876667 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) 337424

[startup+22.4002 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=649016/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=353624 CPUtime=22.26
/proc/25761/stat : 25761 (aptitude) S 25760 25761 17863 34816 17863 4202496 60772 2206 0 0 2200 26 0 0 20 0 2 0 29613642 362110976 55737 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191157216 139970761193035 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 88406 55737 10360 1052 0 63743 0
[pid=25761/tid=25766] ppid=25760 vsize=353624 CPUtime=18.88
/proc/25761/task/25766/stat : 25766 (aptitude) R 25760 25761 17863 34816 17863 4202560 38786 2206 0 0 1874 14 0 0 20 0 2 0 29613719 362110976 55737 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680118368 139970749958521 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 22.26
Current children cumulated vsize (KiB) 353624

[startup+23.2031 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=644552/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=355900 CPUtime=23.07
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 61542 2206 0 0 2280 27 0 0 20 0 2 0 29613642 364441600 56453 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191155592 139970795049944 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 88975 56453 10408 1052 0 64305 0
[pid=25761/tid=25766] ppid=25760 vsize=355900 CPUtime=19.49
/proc/25761/task/25766/stat : 25766 (aptitude) S 25760 25761 17863 34816 17863 4202560 39345 2206 0 0 1934 15 0 0 20 0 2 0 29613719 364441600 56453 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680125440 139970761192148 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 23.07
Current children cumulated vsize (KiB) 355900

[startup+23.6002 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=644552/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=355936 CPUtime=23.46
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 64192 2206 0 0 2319 27 0 0 20 0 2 0 29613642 364478464 56522 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191157160 139970787847882 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 88984 56522 10409 1052 0 64314 0
[pid=25761/tid=25766] ppid=25760 vsize=355936 CPUtime=19.49
/proc/25761/task/25766/stat : 25766 (aptitude) S 25760 25761 17863 34816 17863 4202560 39345 2206 0 0 1934 15 0 0 20 0 2 0 29613719 364478464 56522 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680125440 139970761192148 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 23.46
Current children cumulated vsize (KiB) 355936

[startup+23.8002 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=644552/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=355936 CPUtime=23.66
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 64485 2705 0 0 2330 35 0 1 20 0 2 0 29613642 364478464 56667 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191155544 139970750292037 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 88984 56667 10409 1052 0 64314 0
[pid=25761/tid=25766] ppid=25760 vsize=355936 CPUtime=19.5
/proc/25761/task/25766/stat : 25766 (aptitude) S 25760 25761 17863 34816 17863 4202560 39345 2705 0 0 1934 15 0 1 20 0 2 0 29613719 364478464 56667 18446744073709551615 139970792448000 139970796755352 140737191165456 139970680125440 139970761192148 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 23.66
Current children cumulated vsize (KiB) 355936

[startup+23.9009 s]
/proc/loadavg: 1.00 1.03 1.03 2/57 25767
/proc/meminfo: memFree=644552/1022884 swapFree=0/0
[pid=25761] ppid=25760 vsize=183824 CPUtime=23.77
/proc/25761/stat : 25761 (aptitude) R 25760 25761 17863 34816 17863 4202496 64940 2705 0 0 2335 41 0 1 20 0 1 0 29613642 188235776 4480 18446744073709551615 139970792448000 139970796755352 140737191165456 140737191165016 139970750313962 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/25761/statm: 45956 4480 1508 1052 0 30212 0
Current children cumulated CPU time (s) 23.77
Current children cumulated vsize (KiB) 183824

Child status: 0
Real time (s): 23.904
CPU time (s): 23.7895
CPU user time (s): 23.3615
CPU system time (s): 0.428026
CPU usage (%): 99.521
Max. virtual memory (cumulated for all children) (KiB): 355936

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.3615
system time used= 0.428026
maximum resident set size= 226684
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67712
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= 105
involuntary context switches= 456

runsolver used 0.036002 second user time and 0.076004 second system time

The end