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/22.runsolver.aptitude aptitude -s -y --without-recommends install python2.3-psycopg tct python-xml guile-library ale 

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.05 1.04 1.00 2/55 23091
/proc/meminfo: memFree=957836/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=3152 CPUtime=0
/proc/23091/stat : 23091 (runsolver) D 23090 23091 17863 34816 17863 4202560 76 0 0 0 0 0 0 0 20 0 1 0 28804223 3227648 98 18446744073709551615 134512640 134586868 4289137568 4289135592 4149695391 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23091/statm: 788 98 66 19 0 73 0

[startup+0.188765 s]
/proc/loadavg: 1.05 1.04 1.00 2/55 23091
/proc/meminfo: memFree=957836/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=36128 CPUtime=0
/proc/23091/stat : 23091 (aptitude) D 23090 23091 17863 34816 17863 4202496 168 0 14 0 0 0 0 0 20 0 1 0 28804223 36995072 92 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763187656 140387810071942 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/23091/statm: 9032 92 58 1052 0 39 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 36128

[startup+0.200254 s]
/proc/loadavg: 1.05 1.04 1.00 2/55 23091
/proc/meminfo: memFree=957836/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=40832 CPUtime=0
/proc/23091/stat : 23091 (aptitude) D 23090 23091 17863 34816 17863 4202496 177 0 16 0 0 0 0 0 20 0 1 0 28804223 41811968 101 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763187656 140387810072099 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/23091/statm: 10208 101 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.300364 s]
/proc/loadavg: 1.05 1.04 1.00 2/55 23091
/proc/meminfo: memFree=957836/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=54968 CPUtime=0
/proc/23091/stat : 23091 (aptitude) D 23090 23091 17863 34816 17863 4202496 1072 0 25 0 0 0 0 0 20 0 1 0 28804223 56287232 988 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763187328 140387769900901 0 134217728 4096 0 0 0 0 17 0 0 0 27 0 0
/proc/23091/statm: 13742 988 824 1052 0 106 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54968

[startup+0.700321 s]
/proc/loadavg: 1.05 1.04 1.00 2/55 23091
/proc/meminfo: memFree=957836/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=100508 CPUtime=0.06
/proc/23091/stat : 23091 (aptitude) D 23090 23091 17863 34816 17863 4202496 7612 1705 69 4 4 2 0 0 20 0 1 0 28804223 102920192 7482 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182496 140387807053626 0 134217728 4096 0 0 0 0 17 0 0 0 60 0 0
/proc/23091/statm: 25127 7482 6307 1052 0 1122 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 100508

[startup+1.5002 s]
/proc/loadavg: 1.05 1.04 1.00 2/56 23095
/proc/meminfo: memFree=949884/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=119772 CPUtime=0.51
/proc/23091/stat : 23091 (aptitude) D 23090 23091 17863 34816 17863 4202496 16402 1705 98 4 43 8 0 0 20 0 1 0 28804223 122646528 14777 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763180664 140387780968816 0 134217728 4096 0 0 0 0 17 0 0 0 94 0 0
/proc/23091/statm: 29943 14777 9317 1052 0 5938 0
Current children cumulated CPU time (s) 0.51
Current children cumulated vsize (KiB) 119772

[startup+3.10024 s]
/proc/loadavg: 1.05 1.04 1.00 2/57 23096
/proc/meminfo: memFree=848568/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=132536 CPUtime=1.63
/proc/23091/stat : 23091 (aptitude) R 23090 23091 17863 34816 17863 4202496 19357 1705 98 4 149 14 0 0 20 0 2 0 28804223 135716864 16725 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763178392 140387770365139 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 33134 16725 9585 1052 0 9129 0
[pid=23091/tid=23096] ppid=23090 vsize=132536 CPUtime=0
/proc/23091/task/23096/stat : 23096 (aptitude) S 23090 23091 17863 34816 17863 4202560 4 1705 0 4 0 0 0 0 20 0 2 0 28804436 135716864 16725 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703040000 140387780956884 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 1.63
Current children cumulated vsize (KiB) 132536
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.05 1.04 1.00 2/57 23097
/proc/meminfo: memFree=819676/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=167608 CPUtime=4.78
/proc/23091/stat : 23091 (aptitude) S 23090 23091 17863 34816 17863 4202496 29440 2201 98 6 454 24 0 0 20 0 2 0 28804223 171630592 25628 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182992 140387780957771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 41902 25628 9700 1052 0 17897 0
[pid=23091/tid=23096] ppid=23090 vsize=167608 CPUtime=1.64
/proc/23091/task/23096/stat : 23096 (aptitude) R 23090 23091 17863 34816 17863 4202560 8944 2201 0 6 161 3 0 0 20 0 2 0 28804436 171630592 25628 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703031320 140387814859111 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.78
Current children cumulated vsize (KiB) 167608
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.04 1.04 1.00 2/57 23097
/proc/meminfo: memFree=762884/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=212620 CPUtime=11.15
/proc/23091/stat : 23091 (aptitude) S 23090 23091 17863 34816 17863 4202496 41363 2201 98 6 1088 27 0 0 20 0 2 0 28804223 217722880 36852 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182992 140387780957771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 53155 36852 9700 1052 0 29150 0
[pid=23091/tid=23096] ppid=23090 vsize=212620 CPUtime=8.01
/proc/23091/task/23096/stat : 23096 (aptitude) R 23090 23091 17863 34816 17863 4202560 20867 2201 0 6 794 7 0 0 20 0 2 0 28804436 217722880 36852 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703031320 140387769713432 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 11.15
Current children cumulated vsize (KiB) 212620

[startup+25.5002 s]
/proc/loadavg: 1.03 1.04 1.00 2/57 23097
/proc/meminfo: memFree=686624/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=350828 CPUtime=23.88
/proc/23091/stat : 23091 (aptitude) S 23090 23091 17863 34816 17863 4202496 59529 2201 98 6 2353 35 0 0 20 0 2 0 28804223 359247872 55018 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182992 140387780957771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 87707 55018 9700 1052 0 63702 0
[pid=23091/tid=23096] ppid=23090 vsize=350828 CPUtime=20.75
/proc/23091/task/23096/stat : 23096 (aptitude) R 23090 23091 17863 34816 17863 4202560 39032 2201 0 6 2060 15 0 0 20 0 2 0 28804436 359247872 55018 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703031320 140387813842659 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.88
Current children cumulated vsize (KiB) 350828

[startup+51.1003 s]
/proc/loadavg: 1.02 1.03 1.00 2/57 23097
/proc/meminfo: memFree=528400/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=510848 CPUtime=49.37
/proc/23091/stat : 23091 (aptitude) S 23090 23091 17863 34816 17863 4202496 100060 2201 98 6 4881 56 0 0 20 0 2 0 28804223 523108352 95055 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182992 140387780957771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 127712 95055 9714 1052 0 103707 0
[pid=23091/tid=23096] ppid=23090 vsize=510848 CPUtime=46.22
/proc/23091/task/23096/stat : 23096 (aptitude) R 23090 23091 17863 34816 17863 4202560 79556 2201 0 6 4587 35 0 0 20 0 2 0 28804436 523108352 95055 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703033608 140387814859034 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 49.37
Current children cumulated vsize (KiB) 510848

[startup+102.3 s]
/proc/loadavg: 1.01 1.03 1.00 2/57 23097
/proc/meminfo: memFree=156400/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=879344 CPUtime=100.33
/proc/23091/stat : 23091 (aptitude) S 23090 23091 17863 34816 17863 4202496 192009 2201 98 6 9930 103 0 0 20 0 2 0 28804223 900448256 186990 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182992 140387780957771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 219836 186990 9716 1052 0 195831 0
[pid=23091/tid=23096] ppid=23090 vsize=879344 CPUtime=97.18
/proc/23091/task/23096/stat : 23096 (aptitude) R 23090 23091 17863 34816 17863 4202560 171505 2201 0 6 9635 83 0 0 20 0 2 0 28804436 900448256 186990 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703031320 140387770365139 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 100.33
Current children cumulated vsize (KiB) 879344



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+148.1 s]
/proc/loadavg: 1.21 1.07 1.01 2/57 23097
/proc/meminfo: memFree=9992/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=1151500 CPUtime=144.35
/proc/23091/stat : 23091 (aptitude) S 23090 23091 17863 34816 17863 4202496 260127 2201 141 6 14284 151 0 0 20 0 2 0 28804223 1179136000 244841 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182992 140387780957771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 287875 244841 9710 1052 0 263870 0
[pid=23091/tid=23096] ppid=23090 vsize=1151500 CPUtime=141.2
/proc/23091/task/23096/stat : 23096 (aptitude) R 23090 23091 17863 34816 17863 4202560 239623 2201 43 6 13989 131 0 0 20 0 2 0 28804436 1179136000 244841 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703033432 140387814423642 0 134217728 4096 0 0 0 0 -1 0 0 0 118 0 0
Current children cumulated CPU time (s) 144.35
Current children cumulated vsize (KiB) 1151500

Sending Terminated to process tree (bottom up)
Sleeping 2 seconds

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

[startup+148.1 s]
/proc/loadavg: 1.21 1.07 1.01 2/57 23097
/proc/meminfo: memFree=9992/1022884 swapFree=0/0
[pid=23091] ppid=23090 vsize=1151500 CPUtime=144.35
/proc/23091/stat : 23091 (aptitude) S 23090 23091 17863 34816 17863 4202496 260127 2201 141 6 14284 151 0 0 20 0 2 0 28804223 1179136000 244841 18446744073709551615 140387812212736 140387816520088 140733763191232 140733763182992 140387780957771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 141 0 0
/proc/23091/statm: 287875 244841 9710 1052 0 263870 0
[pid=23091/tid=23096] ppid=23090 vsize=1151500 CPUtime=141.2
/proc/23091/task/23096/stat : 23096 (aptitude) R 23090 23091 17863 34816 17863 4202560 239623 2201 43 6 13989 131 0 0 20 0 2 0 28804436 1179136000 244841 18446744073709551615 140387812212736 140387816520088 140733763191232 140387703033432 140387814423642 0 134217728 4096 0 0 0 0 -1 0 0 0 118 0 0
Current children cumulated CPU time (s) 144.35
Current children cumulated vsize (KiB) 1151500

Child ended because it received signal 15 (SIGTERM)
Real time (s): 148.222
CPU time (s): 144.457
CPU user time (s): 142.893
CPU system time (s): 1.5641
CPU usage (%): 97.4601
Max. virtual memory (cumulated for all children) (KiB): 1151500

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 142.893
system time used= 1.5641
maximum resident set size= 981332
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262341
page faults= 147
swaps= 0
block input operations= 182448
block output operations= 64
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2091
involuntary context switches= 3199

runsolver used 0.176011 second user time and 0.524032 second system time

The end