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/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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.24 1.07 0.96 2/55 21629
/proc/meminfo: memFree=909316/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=54860 CPUtime=0
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 605 0 0 0 0 0 0 0 20 0 1 0 28502612 56176640 504 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824374024 140376567805895 0 0 0 0 0 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 13715 504 412 1052 0 73 0

[startup+0.13086 s]
/proc/loadavg: 1.24 1.07 0.96 2/55 21629
/proc/meminfo: memFree=909316/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=89152 CPUtime=0.11
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 7771 1707 0 0 9 2 0 0 20 0 1 0 28502612 91291648 7570 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366080 140376564836675 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 22288 7570 6659 1052 0 858 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 89152

[startup+0.200294 s]
/proc/loadavg: 1.24 1.07 0.96 2/55 21629
/proc/meminfo: memFree=909316/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=89152 CPUtime=0.18
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 7871 1707 0 0 16 2 0 0 20 0 1 0 28502612 91291648 7662 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824364592 140376565395558 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.300337 s]
/proc/loadavg: 1.24 1.07 0.96 2/55 21629
/proc/meminfo: memFree=909316/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=101864 CPUtime=0.29
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 11710 1707 0 0 25 4 0 0 20 0 1 0 28502612 104308736 10756 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824364248 140376538751344 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.700198 s]
/proc/loadavg: 1.24 1.07 0.96 2/55 21629
/proc/meminfo: memFree=909316/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=114196 CPUtime=0.68
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 13726 1707 0 0 62 6 0 0 20 0 2 0 28502612 116936704 12098 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366088 140376536308025 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 28549 12098 6977 1052 0 7119 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 114196

[startup+1.50029 s]
/proc/loadavg: 1.24 1.07 0.96 2/57 21634
/proc/meminfo: memFree=888476/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=115360 CPUtime=1.48
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 14597 2211 0 0 140 8 0 0 20 0 2 0 28502612 118128640 12347 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366840 140376572233959 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 28840 12347 7073 1052 0 7410 0
[pid=21629/tid=21634] ppid=21628 vsize=115360 CPUtime=0
/proc/21629/task/21634/stat : 21634 (aptitude) S 21628 21629 17863 34816 17863 4202560 6 2211 0 0 0 0 0 0 20 0 2 0 28502656 118128640 12347 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473401344 140376538739412 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) 115360

[startup+3.1003 s]
/proc/loadavg: 1.22 1.07 0.96 2/57 21635
/proc/meminfo: memFree=880416/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=132652 CPUtime=3.06
/proc/21629/stat : 21629 (aptitude) S 21628 21629 17863 34816 17863 4202496 19524 2211 0 0 296 10 0 0 20 0 2 0 28502612 135835648 16901 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366576 140376538740299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 33163 16901 7129 1052 0 11733 0
[pid=21629/tid=21634] ppid=21628 vsize=132652 CPUtime=1.1
/proc/21629/task/21634/stat : 21634 (aptitude) R 21628 21629 17863 34816 17863 4202560 4906 2211 0 0 108 2 0 0 20 0 2 0 28502656 135835648 16901 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473394872 140376572709607 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.06
Current children cumulated vsize (KiB) 132652

[startup+6.30024 s]
/proc/loadavg: 1.22 1.07 0.96 2/57 21635
/proc/meminfo: memFree=846440/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=164316 CPUtime=6.25
/proc/21629/stat : 21629 (aptitude) S 21628 21629 17863 34816 17863 4202496 27749 2211 0 0 611 14 0 0 20 0 2 0 28502612 168259584 24781 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366576 140376538740299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 41079 24781 7129 1052 0 19649 0
[pid=21629/tid=21634] ppid=21628 vsize=164316 CPUtime=4.29
/proc/21629/task/21634/stat : 21634 (aptitude) R 21628 21629 17863 34816 17863 4202560 13131 2211 0 0 423 6 0 0 20 0 2 0 28502656 168259584 24781 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473392664 140376564823024 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) 164316

[startup+12.7003 s]
/proc/loadavg: 1.18 1.07 0.96 2/57 21635
/proc/meminfo: memFree=791632/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=281360 CPUtime=12.62
/proc/21629/stat : 21629 (aptitude) S 21628 21629 17863 34816 17863 4202496 40639 2211 0 0 1242 20 0 0 20 0 2 0 28502612 288112640 37651 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366576 140376538740299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 70340 37651 7129 1052 0 48910 0
[pid=21629/tid=21634] ppid=21628 vsize=281360 CPUtime=10.66
/proc/21629/task/21634/stat : 21634 (aptitude) R 21628 21629 17863 34816 17863 4202560 26020 2211 0 0 1053 13 0 0 20 0 2 0 28502656 288112640 37651 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473394872 140376527495507 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) 281360

[startup+25.5003 s]
/proc/loadavg: 1.16 1.06 0.96 2/57 21635
/proc/meminfo: memFree=692184/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=376244 CPUtime=25.36
/proc/21629/stat : 21629 (aptitude) S 21628 21629 17863 34816 17863 4202496 64588 2211 0 0 2506 30 0 0 20 0 2 0 28502612 385273856 61375 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366576 140376538740299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 94061 61375 7129 1052 0 72631 0
[pid=21629/tid=21634] ppid=21628 vsize=376244 CPUtime=23.39
/proc/21629/task/21634/stat : 21634 (aptitude) R 21628 21629 17863 34816 17863 4202560 49969 2211 0 0 2317 22 0 0 20 0 2 0 28502656 385273856 61375 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473392664 140376536307808 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.36
Current children cumulated vsize (KiB) 376244

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

[startup+25.6004 s]
/proc/loadavg: 1.16 1.06 0.96 2/57 21635
/proc/meminfo: memFree=692184/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=376640 CPUtime=25.46
/proc/21629/stat : 21629 (aptitude) S 21628 21629 17863 34816 17863 4202496 64673 2211 0 0 2516 30 0 0 20 0 2 0 28502612 385679360 61460 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366576 140376538740299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 94160 61460 7129 1052 0 72730 0
[pid=21629/tid=21634] ppid=21628 vsize=376640 CPUtime=23.49
/proc/21629/task/21634/stat : 21634 (aptitude) R 21628 21629 17863 34816 17863 4202560 50054 2211 0 0 2327 22 0 0 20 0 2 0 28502656 385679360 61460 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473394872 140376572822175 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.46
Current children cumulated vsize (KiB) 376640

[startup+28.8002 s]
/proc/loadavg: 1.14 1.06 0.96 2/57 21635
/proc/meminfo: memFree=680404/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=388552 CPUtime=28.63
/proc/21629/stat : 21629 (aptitude) S 21628 21629 17863 34816 17863 4202496 67649 2211 0 0 2832 31 0 0 20 0 2 0 28502612 397877248 64434 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366576 140376538740299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 97138 64434 7129 1052 0 75708 0
[pid=21629/tid=21634] ppid=21628 vsize=388552 CPUtime=26.67
/proc/21629/task/21634/stat : 21634 (aptitude) R 21628 21629 17863 34816 17863 4202560 53030 2211 0 0 2644 23 0 0 20 0 2 0 28502656 397877248 64434 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473392664 140376527505661 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 28.63
Current children cumulated vsize (KiB) 388552

[startup+30.4003 s]
/proc/loadavg: 1.14 1.06 0.96 2/57 21635
/proc/meminfo: memFree=674576/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=396784 CPUtime=30.23
/proc/21629/stat : 21629 (aptitude) S 21628 21629 17863 34816 17863 4202496 69725 2211 0 0 2991 32 0 0 20 0 2 0 28502612 406306816 66508 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366576 140376538740299 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 99196 66508 7129 1052 0 77766 0
[pid=21629/tid=21634] ppid=21628 vsize=396784 CPUtime=28.26
/proc/21629/task/21634/stat : 21634 (aptitude) R 21628 21629 17863 34816 17863 4202560 55106 2211 0 0 2802 24 0 0 20 0 2 0 28502656 406306816 66508 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473394872 140376527505504 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 30.23
Current children cumulated vsize (KiB) 396784

[startup+31.2003 s]
/proc/loadavg: 1.14 1.06 0.96 2/57 21635
/proc/meminfo: memFree=668376/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=400352 CPUtime=31.02
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 70974 2211 0 0 3069 33 0 0 20 0 2 0 28502612 409960448 67627 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824364952 140376527486526 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 100088 67627 7178 1052 0 78651 0
[pid=21629/tid=21634] ppid=21628 vsize=400352 CPUtime=28.72
/proc/21629/task/21634/stat : 21634 (aptitude) S 21628 21629 17863 34816 17863 4202560 55972 2211 0 0 2848 24 0 0 20 0 2 0 28502656 409960448 67627 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473401344 140376538739412 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 31.02
Current children cumulated vsize (KiB) 400352

[startup+31.6003 s]
/proc/loadavg: 1.14 1.06 0.96 2/57 21635
/proc/meminfo: memFree=668376/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=400352 CPUtime=31.42
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 71685 2211 0 0 3109 33 0 0 20 0 2 0 28502612 409960448 67628 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824362680 140376564848629 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 100088 67628 7179 1052 0 78651 0
[pid=21629/tid=21634] ppid=21628 vsize=400352 CPUtime=28.72
/proc/21629/task/21634/stat : 21634 (aptitude) S 21628 21629 17863 34816 17863 4202560 55972 2211 0 0 2848 24 0 0 20 0 2 0 28502656 409960448 67628 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473401344 140376538739412 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 31.42
Current children cumulated vsize (KiB) 400352

[startup+31.8003 s]
/proc/loadavg: 1.14 1.06 0.96 2/57 21635
/proc/meminfo: memFree=668376/1022884 swapFree=0/0
[pid=21629] ppid=21628 vsize=400352 CPUtime=31.62
/proc/21629/stat : 21629 (aptitude) R 21628 21629 17863 34816 17863 4202496 72973 2711 0 0 3122 39 0 1 20 0 2 0 28502612 409960448 67607 18446744073709551615 140376569995264 140376574302616 140733824374816 140733824366416 140376536300501 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21629/statm: 100088 67607 7179 1052 0 78651 0
[pid=21629/tid=21634] ppid=21628 vsize=400352 CPUtime=28.73
/proc/21629/task/21634/stat : 21634 (aptitude) S 21628 21629 17863 34816 17863 4202560 55972 2711 0 0 2848 24 0 1 20 0 2 0 28502656 409960448 67607 18446744073709551615 140376569995264 140376574302616 140733824374816 140376473401344 140376538739412 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 31.62
Current children cumulated vsize (KiB) 400352

Child status: 0
Real time (s): 31.8835
CPU time (s): 31.73
CPU user time (s): 31.25
CPU system time (s): 0.48003
CPU usage (%): 99.5184
Max. virtual memory (cumulated for all children) (KiB): 400352

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 31.25
system time used= 0.48003
maximum resident set size= 270840
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 76416
page faults= 0
swaps= 0
block input operations= 0
block output operations= 128
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 120
involuntary context switches= 598

runsolver used 0.056003 second user time and 0.108006 second system time

The end