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/63.runsolver.aptitude aptitude -s -y --without-recommends install python2.1-xmms knotes lapack-dev libkrb5-dev genparse 

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.28 1.10 1.04 2/55 25779
/proc/meminfo: memFree=959868/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=3152 CPUtime=0
/proc/25779/stat : 25779 (runsolver) R 25778 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29627366 3227648 33 18446744073709551615 134512640 134586868 4292452160 4292450208 4152009776 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25779/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.123543 s]
/proc/loadavg: 1.28 1.10 1.04 2/55 25779
/proc/meminfo: memFree=959868/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=14396 CPUtime=0
/proc/25779/stat : 25779 (aptitude) D 25778 25779 17863 34816 17863 4202496 133 0 6 0 0 0 0 0 20 0 1 0 29627366 14741504 55 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590557320 139804804272906 0 0 0 0 0 0 0 17 0 0 0 11 0 0
/proc/25779/statm: 3599 55 38 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 14396

[startup+0.20036 s]
/proc/loadavg: 1.28 1.10 1.04 2/55 25779
/proc/meminfo: memFree=959868/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=36128 CPUtime=0
/proc/25779/stat : 25779 (aptitude) D 25778 25779 17863 34816 17863 4202496 168 0 14 0 0 0 0 0 20 0 1 0 29627366 36995072 92 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590556840 139804804273542 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/25779/statm: 9032 92 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.300411 s]
/proc/loadavg: 1.28 1.10 1.04 2/55 25779
/proc/meminfo: memFree=959868/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=54968 CPUtime=0
/proc/25779/stat : 25779 (aptitude) D 25778 25779 17863 34816 17863 4202496 1071 0 25 0 0 0 0 0 20 0 1 0 29627366 56287232 987 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590556512 139804764102501 0 134217728 4096 0 0 0 0 17 0 0 0 27 0 0
/proc/25779/statm: 13742 987 824 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700334 s]
/proc/loadavg: 1.28 1.10 1.04 2/55 25779
/proc/meminfo: memFree=959868/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=103288 CPUtime=0.02
/proc/25779/stat : 25779 (aptitude) D 25778 25779 17863 34816 17863 4202496 2730 1705 68 4 0 2 0 0 20 0 1 0 29627366 105766912 2600 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590551888 139804801464218 0 134217728 4096 0 0 0 0 17 0 0 0 62 0 0
/proc/25779/statm: 25822 2600 1388 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.50033 s]
/proc/loadavg: 1.28 1.10 1.04 1/56 25783
/proc/meminfo: memFree=951180/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=103288 CPUtime=0.03
/proc/25779/stat : 25779 (aptitude) D 25778 25779 17863 34816 17863 4202496 5767 1705 202 4 0 3 0 0 20 0 1 0 29627366 105766912 5771 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590551888 139804801464218 0 134217728 4096 0 0 0 0 17 0 0 0 141 0 0
/proc/25779/statm: 25822 5771 4559 1052 0 1159 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 103288

[startup+3.10024 s]
/proc/loadavg: 1.28 1.10 1.04 2/56 25783
/proc/meminfo: memFree=934192/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=123068 CPUtime=0.75
/proc/25779/stat : 25779 (aptitude) R 25778 25779 17863 34816 17863 4202496 17432 1705 255 4 58 17 0 0 20 0 1 0 29627366 126021632 15965 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590549848 139804801314977 0 134217728 4096 0 0 0 0 17 0 0 0 229 0 0
/proc/25779/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.75
Current children cumulated vsize (KiB) 123068
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.34 1.11 1.05 2/57 25785
/proc/meminfo: memFree=803736/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=144412 CPUtime=3.7
/proc/25779/stat : 25779 (aptitude) S 25778 25779 17863 34816 17863 4202496 23695 2202 255 6 342 27 1 0 20 0 2 0 29627366 147877888 19810 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590552176 139804775159371 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/25779/statm: 36103 19810 10355 1052 0 11440 0
[pid=25779/tid=25784] ppid=25778 vsize=144412 CPUtime=0.23
/proc/25779/task/25784/stat : 25784 (aptitude) R 25778 25779 17863 34816 17863 4202560 1951 2202 0 6 22 0 1 0 20 0 2 0 29627702 147877888 19810 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694083112 139804809188403 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.7
Current children cumulated vsize (KiB) 144412
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.31 1.11 1.05 2/57 25785
/proc/meminfo: memFree=731568/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=278324 CPUtime=10.07
/proc/25779/stat : 25779 (aptitude) S 25778 25779 17863 34816 17863 4202496 41344 2202 255 6 972 34 1 0 20 0 2 0 29627366 285003776 36928 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590552176 139804775159371 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/25779/statm: 69581 36928 10359 1052 0 44918 0
[pid=25779/tid=25784] ppid=25778 vsize=278324 CPUtime=6.6
/proc/25779/task/25784/stat : 25784 (aptitude) R 25778 25779 17863 34816 17863 4202560 19598 2202 0 6 652 7 1 0 20 0 2 0 29627702 285003776 36928 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694083096 139804763924857 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.07
Current children cumulated vsize (KiB) 278324
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.24 1.10 1.05 2/57 25785
/proc/meminfo: memFree=654316/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=352952 CPUtime=22.8
/proc/25779/stat : 25779 (aptitude) S 25778 25779 17863 34816 17863 4202496 60334 2202 255 6 2237 42 1 0 20 0 2 0 29627366 361422848 55559 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590552176 139804775159371 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/25779/statm: 88238 55559 10360 1052 0 63575 0
[pid=25779/tid=25784] ppid=25778 vsize=352952 CPUtime=19.34
/proc/25779/task/25784/stat : 25784 (aptitude) R 25778 25779 17863 34816 17863 4202560 38588 2202 0 6 1917 16 1 0 20 0 2 0 29627702 361422848 55559 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694086360 139804809011376 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.8
Current children cumulated vsize (KiB) 352952

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

[startup+25.6003 s]
/proc/loadavg: 1.24 1.10 1.05 2/57 25785
/proc/meminfo: memFree=654316/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=353892 CPUtime=22.9
/proc/25779/stat : 25779 (aptitude) S 25778 25779 17863 34816 17863 4202496 60561 2202 255 6 2247 42 1 0 20 0 2 0 29627366 362385408 55786 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590552176 139804775159371 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/25779/statm: 88473 55786 10360 1052 0 63810 0
[pid=25779/tid=25784] ppid=25778 vsize=353892 CPUtime=19.44
/proc/25779/task/25784/stat : 25784 (aptitude) R 25778 25779 17863 34816 17863 4202560 38815 2202 0 6 1927 16 1 0 20 0 2 0 29627702 362385408 55786 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694083224 139804772347550 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.9
Current children cumulated vsize (KiB) 353892

[startup+28.8002 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25785
/proc/meminfo: memFree=638444/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=368688 CPUtime=26.09
/proc/25779/stat : 25779 (aptitude) S 25778 25779 17863 34816 17863 4202496 64290 2202 255 6 2563 45 1 0 20 0 2 0 29627366 377536512 59490 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590552176 139804775159371 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/25779/statm: 92172 59490 10360 1052 0 67509 0
[pid=25779/tid=25784] ppid=25778 vsize=368688 CPUtime=22.62
/proc/25779/task/25784/stat : 25784 (aptitude) R 25778 25779 17863 34816 17863 4202560 42544 2202 0 6 2243 18 1 0 20 0 2 0 29627702 377536512 59490 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694083096 139804801815105 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 26.09
Current children cumulated vsize (KiB) 368688

[startup+29.6003 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25785
/proc/meminfo: memFree=638444/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=372000 CPUtime=26.86
/proc/25779/stat : 25779 (aptitude) D 25778 25779 17863 34816 17863 4202496 65137 2202 256 6 2640 45 1 0 20 0 2 0 29627366 380928000 60338 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590552104 139804807748112 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 252 0 0
/proc/25779/statm: 93000 60338 10362 1052 0 68337 0
[pid=25779/tid=25784] ppid=25778 vsize=372000 CPUtime=23.4
/proc/25779/task/25784/stat : 25784 (aptitude) S 25778 25779 17863 34816 17863 4202560 43391 2202 1 6 2320 19 1 0 20 0 2 0 29627702 380928000 60338 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694091776 139804775158484 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 26.86
Current children cumulated vsize (KiB) 372000

[startup+30.4002 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25785
/proc/meminfo: memFree=632616/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=372068 CPUtime=27.59
/proc/25779/stat : 25779 (aptitude) R 25778 25779 17863 34816 17863 4202496 67996 2202 268 6 2712 46 1 0 20 0 2 0 29627366 380997632 60582 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590552232 139804763601552 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 260 0 0
/proc/25779/statm: 93017 60582 10409 1052 0 68347 0
[pid=25779/tid=25784] ppid=25778 vsize=372068 CPUtime=23.4
/proc/25779/task/25784/stat : 25784 (aptitude) S 25778 25779 17863 34816 17863 4202560 43391 2202 1 6 2320 19 1 0 20 0 2 0 29627702 380997632 60582 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694091776 139804775158484 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 27.59
Current children cumulated vsize (KiB) 372068

[startup+30.6002 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25785
/proc/meminfo: memFree=632616/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=372068 CPUtime=27.78
/proc/25779/stat : 25779 (aptitude) R 25778 25779 17863 34816 17863 4202496 68287 2702 268 6 2723 54 1 0 20 0 2 0 29627366 380997632 60714 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590551128 139804801406000 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 260 0 0
/proc/25779/statm: 93017 60714 10409 1052 0 68347 0
[pid=25779/tid=25784] ppid=25778 vsize=372068 CPUtime=23.4
/proc/25779/task/25784/stat : 25784 (aptitude) S 25778 25779 17863 34816 17863 4202560 43391 2702 1 6 2320 19 1 0 20 0 2 0 29627702 380997632 60714 18446744073709551615 139804806414336 139804810721688 140734590560416 139804694091776 139804775158484 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 27.78
Current children cumulated vsize (KiB) 372068

[startup+30.7007 s]
/proc/loadavg: 1.22 1.10 1.05 2/57 25785
/proc/meminfo: memFree=632616/1022884 swapFree=0/0
[pid=25779] ppid=25778 vsize=304364 CPUtime=27.86
/proc/25779/stat : 25779 (aptitude) R 25778 25779 17863 34816 17863 4202496 68708 2702 270 6 2728 57 1 0 20 0 1 0 29627366 311668736 42541 18446744073709551615 139804806414336 139804810721688 140734590560416 140734590557464 139804764280298 0 134217728 4096 0 0 0 0 17 0 0 0 262 0 0
/proc/25779/statm: 76091 42541 10412 1052 0 51421 0
Current children cumulated CPU time (s) 27.86
Current children cumulated vsize (KiB) 304364

Child status: 0
Real time (s): 30.7918
CPU time (s): 27.9297
CPU user time (s): 27.3097
CPU system time (s): 0.620038
CPU usage (%): 90.7052
Max. virtual memory (cumulated for all children) (KiB): 372068

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 27.3097
system time used= 0.620038
maximum resident set size= 242884
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 71503
page faults= 291
swaps= 0
block input operations= 254208
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2498
involuntary context switches= 539

runsolver used 0 second user time and 0.156009 second system time

The end