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/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.23 1.09 1.02 2/55 23702
/proc/meminfo: memFree=961592/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=3152 CPUtime=0
/proc/23702/stat : 23702 (runsolver) D 23701 23702 17863 34816 17863 4202560 76 0 0 0 0 0 0 0 20 0 1 0 28987489 3227648 98 18446744073709551615 134512640 134586868 4290445440 4290443464 4149654431 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23702/statm: 788 98 66 19 0 73 0

[startup+0.189142 s]
/proc/loadavg: 1.23 1.09 1.02 2/55 23702
/proc/meminfo: memFree=961592/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=54860 CPUtime=0
/proc/23702/stat : 23702 (aptitude) D 23701 23702 17863 34816 17863 4202496 627 0 17 0 0 0 0 0 20 0 1 0 28987489 56176640 544 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552410168 140009013356473 0 0 0 0 0 0 0 17 0 0 0 17 0 0
/proc/23702/statm: 13715 544 448 1052 0 73 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54860

[startup+0.200394 s]
/proc/loadavg: 1.23 1.09 1.02 2/55 23702
/proc/meminfo: memFree=961592/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=54972 CPUtime=0
/proc/23702/stat : 23702 (aptitude) D 23701 23702 17863 34816 17863 4202496 1000 0 19 0 0 0 0 0 20 0 1 0 28987489 56291328 911 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552407480 140008973391600 0 134217728 0 0 0 0 0 17 0 0 0 18 0 0
/proc/23702/statm: 13743 911 760 1052 0 107 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54972

[startup+0.300397 s]
/proc/loadavg: 1.23 1.09 1.02 2/55 23702
/proc/meminfo: memFree=961592/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=63380 CPUtime=0.01
/proc/23702/stat : 23702 (aptitude) D 23701 23702 17863 34816 17863 4202496 1202 0 19 0 1 0 0 0 20 0 1 0 28987489 64901120 1097 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552403960 140008984301936 0 134217728 4096 0 0 0 0 17 0 0 0 27 0 0
/proc/23702/statm: 15845 1097 919 1052 0 108 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 63380

[startup+0.700328 s]
/proc/loadavg: 1.23 1.09 1.02 2/55 23702
/proc/meminfo: memFree=961592/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=100508 CPUtime=0.01
/proc/23702/stat : 23702 (aptitude) D 23701 23702 17863 34816 17863 4202496 2756 1705 55 2 1 0 0 0 20 0 1 0 28987489 102920192 2610 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552402432 140009010595738 0 134217728 4096 0 0 0 0 17 0 0 0 60 0 0
/proc/23702/statm: 25127 2610 1436 1052 0 1122 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 100508

[startup+1.50033 s]
/proc/loadavg: 1.23 1.09 1.02 1/56 23706
/proc/meminfo: memFree=953524/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=100508 CPUtime=0.03
/proc/23702/stat : 23702 (aptitude) D 23701 23702 17863 34816 17863 4202496 5457 1705 176 2 2 1 0 0 20 0 1 0 28987489 102920192 5432 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552402432 140009010595738 0 134217728 4096 0 0 0 0 17 0 0 0 139 0 0
/proc/23702/statm: 25127 5432 4258 1052 0 1122 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 100508

[startup+3.10024 s]
/proc/loadavg: 1.22 1.09 1.02 1/56 23706
/proc/meminfo: memFree=951416/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=119772 CPUtime=0.63
/proc/23702/stat : 23702 (aptitude) D 23701 23702 17863 34816 17863 4202496 16263 1705 246 2 53 10 0 0 20 0 1 0 28987489 122646528 14785 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552400392 140008984301936 0 134217728 4096 0 0 0 0 17 0 0 0 238 0 0
/proc/23702/statm: 29943 14785 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.63
Current children cumulated vsize (KiB) 119772
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.22 1.09 1.02 2/57 23708
/proc/meminfo: memFree=838196/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=211752 CPUtime=3.69
/proc/23702/stat : 23702 (aptitude) S 23701 23702 17863 34816 17863 4202496 23764 2201 246 4 348 20 1 0 20 0 2 0 28987489 216834048 20275 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552402720 140008984290891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 251 0 0
/proc/23702/statm: 52938 20275 9698 1052 0 28933 0
[pid=23702/tid=23707] ppid=23701 vsize=211752 CPUtime=0.54
/proc/23702/task/23707/stat : 23707 (aptitude) R 23701 23702 17863 34816 17863 4202560 3404 2201 0 4 51 2 1 0 20 0 2 0 28987814 216834048 20275 18446744073709551615 140009015545856 140009019853208 140735552410960 140008906366552 140009018142896 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.69
Current children cumulated vsize (KiB) 211752
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.18 1.09 1.01 2/57 23708
/proc/meminfo: memFree=772972/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=269776 CPUtime=10.06
/proc/23702/stat : 23702 (aptitude) S 23701 23702 17863 34816 17863 4202496 39087 2201 246 4 978 27 1 0 20 0 2 0 28987489 276250624 34760 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552402720 140008984290891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 251 0 0
/proc/23702/statm: 67444 34760 9700 1052 0 43439 0
[pid=23702/tid=23707] ppid=23701 vsize=269776 CPUtime=6.9
/proc/23702/task/23707/stat : 23707 (aptitude) R 23701 23702 17863 34816 17863 4202560 18727 2201 0 4 680 9 1 0 20 0 2 0 28987814 276250624 34760 18446744073709551615 140009015545856 140009019853208 140735552410960 140008906367592 140009018057904 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.06
Current children cumulated vsize (KiB) 269776
heavy processes:

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

[startup+12.8074 s]
/proc/loadavg: 1.18 1.09 1.01 2/57 23708
/proc/meminfo: memFree=767144/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=270568 CPUtime=10.16
/proc/23702/stat : 23702 (aptitude) S 23701 23702 17863 34816 17863 4202496 39287 2201 246 4 988 27 1 0 20 0 2 0 28987489 277061632 34960 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552402720 140008984290891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 251 0 0
/proc/23702/statm: 67642 34960 9700 1052 0 43637 0
[pid=23702/tid=23707] ppid=23701 vsize=270568 CPUtime=7
/proc/23702/task/23707/stat : 23707 (aptitude) R 23701 23702 17863 34816 17863 4202560 18927 2201 0 4 690 9 1 0 20 0 2 0 28987814 277061632 34960 18446744073709551615 140009015545856 140009019853208 140735552410960 140008906364392 140009018192146 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.16
Current children cumulated vsize (KiB) 270568

[startup+13.6002 s]
/proc/loadavg: 1.18 1.09 1.01 2/57 23708
/proc/meminfo: memFree=763300/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=274580 CPUtime=10.95
/proc/23702/stat : 23702 (aptitude) R 23701 23702 17863 34816 17863 4202496 41302 2201 246 4 1066 28 1 0 20 0 2 0 28987489 281169920 36124 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552398824 140009017670786 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 251 0 0
/proc/23702/statm: 68645 36124 9750 1052 0 44633 0
[pid=23702/tid=23707] ppid=23701 vsize=274580 CPUtime=7.5
/proc/23702/task/23707/stat : 23707 (aptitude) S 23701 23702 17863 34816 17863 4202560 19914 2201 0 4 740 9 1 0 20 0 2 0 28987814 281169920 36124 18446744073709551615 140009015545856 140009019853208 140735552410960 140008906373120 140008984290004 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.95
Current children cumulated vsize (KiB) 274580

[startup+14.0011 s]
/proc/loadavg: 1.18 1.09 1.01 2/57 23708
/proc/meminfo: memFree=763300/1022884 swapFree=0/0
[pid=23702] ppid=23701 vsize=250512 CPUtime=11.36
/proc/23702/stat : 23702 (aptitude) R 23701 23702 17863 34816 17863 4202496 43787 2700 246 4 1097 37 1 1 20 0 1 0 28987489 256524288 27028 18446744073709551615 140009015545856 140009019853208 140735552410960 140735552408008 140008973411818 0 134217728 4096 0 0 0 0 17 0 0 0 251 0 0
/proc/23702/statm: 62628 27028 9753 1052 0 38616 0
Current children cumulated CPU time (s) 11.36
Current children cumulated vsize (KiB) 250512

Child status: 0
Real time (s): 14.0283
CPU time (s): 11.3967
CPU user time (s): 10.9887
CPU system time (s): 0.408025
CPU usage (%): 81.2409
Max. virtual memory (cumulated for all children) (KiB): 274580

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.9887
system time used= 0.408025
maximum resident set size= 145296
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 46594
page faults= 250
swaps= 0
block input operations= 187224
block output operations= 144
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1906
involuntary context switches= 259

runsolver used 0.008 second user time and 0.068004 second system time

The end