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/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

[startup+0 s]
/proc/loadavg: 1.19 1.10 1.03 2/55 25167
/proc/meminfo: memFree=954572/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=3152 CPUtime=0
/proc/25167/stat : 25167 (runsolver) R 25166 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29369368 3227648 32 18446744073709551615 134512640 134586868 4292665632 4292663680 4151960624 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25167/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.192984 s]
/proc/loadavg: 1.19 1.10 1.03 2/55 25167
/proc/meminfo: memFree=954572/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=23840 CPUtime=0
/proc/25167/stat : 25167 (aptitude) D 25166 25167 17863 34816 17863 4202496 145 0 9 0 0 0 0 0 20 0 1 0 29369368 24412160 68 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049347608 140417234268942 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/25167/statm: 5960 68 45 1052 0 31 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.200405 s]
/proc/loadavg: 1.19 1.10 1.03 2/55 25167
/proc/meminfo: memFree=954572/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=23840 CPUtime=0
/proc/25167/stat : 25167 (aptitude) D 25166 25167 17863 34816 17863 4202496 150 0 10 0 0 0 0 0 20 0 1 0 29369368 24412160 73 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049348152 140417234264535 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/25167/statm: 5960 73 48 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 23840

[startup+0.300375 s]
/proc/loadavg: 1.19 1.10 1.03 2/55 25167
/proc/meminfo: memFree=954572/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=38696 CPUtime=0
/proc/25167/stat : 25167 (aptitude) D 25166 25167 17863 34816 17863 4202496 173 0 15 0 0 0 0 0 20 0 1 0 29369368 39624704 97 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049347224 140417234268918 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/25167/statm: 9674 97 61 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 38696

[startup+0.700329 s]
/proc/loadavg: 1.19 1.10 1.03 2/55 25167
/proc/meminfo: memFree=954572/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=103288 CPUtime=0.02
/proc/25167/stat : 25167 (aptitude) D 25166 25167 17863 34816 17863 4202496 3450 1704 39 4 0 2 0 0 20 0 1 0 29369368 105766912 3291 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342368 140417231460250 0 134217728 4096 0 0 0 0 17 0 0 0 63 0 0
/proc/25167/statm: 25822 3291 2079 1052 0 1159 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 103288

[startup+1.50021 s]
/proc/loadavg: 1.19 1.10 1.03 2/56 25171
/proc/meminfo: memFree=947364/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=123068 CPUtime=0.5
/proc/25167/stat : 25167 (aptitude) D 25166 25167 17863 34816 17863 4202496 17587 1704 78 4 44 6 0 0 20 0 1 0 29369368 126021632 15943 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049340328 140417205166448 0 134217728 4096 0 0 0 0 17 0 0 0 95 0 0
/proc/25167/statm: 30767 15943 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.5
Current children cumulated vsize (KiB) 123068

[startup+3.10021 s]
/proc/loadavg: 1.18 1.10 1.03 2/56 25171
/proc/meminfo: memFree=848660/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=136064 CPUtime=1.37
/proc/25167/stat : 25167 (aptitude) R 25166 25167 17863 34816 17863 4202496 20565 1704 78 4 120 17 0 0 20 0 2 0 29369368 139329536 17562 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342168 140417237239393 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 167 0 0
/proc/25167/statm: 34016 17562 10207 1052 0 9353 0
Current children cumulated CPU time (s) 1.37
Current children cumulated vsize (KiB) 136064
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.18 1.10 1.03 2/57 25173
/proc/meminfo: memFree=796696/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=160656 CPUtime=4.52
/proc/25167/stat : 25167 (aptitude) S 25166 25167 17863 34816 17863 4202496 27950 2201 78 6 425 27 0 0 20 0 2 0 29369368 164511744 23868 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342656 140417205155403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 169 0 0
/proc/25167/statm: 40164 23868 10359 1052 0 15501 0
[pid=25167/tid=25172] ppid=25166 vsize=160656 CPUtime=1.05
/proc/25167/task/25172/stat : 25172 (aptitude) R 25166 25167 17863 34816 17863 4202560 6040 2201 0 6 103 2 0 0 20 0 2 0 29369621 164511744 23868 18446744073709551615 140417236410368 140417240717720 140736049350896 140417124081336 140417193920608 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.52
Current children cumulated vsize (KiB) 160656
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.15 1.09 1.03 2/57 25173
/proc/meminfo: memFree=725768/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=219528 CPUtime=10.89
/proc/25167/stat : 25167 (aptitude) S 25166 25167 17863 34816 17863 4202496 43200 2201 78 6 1054 35 0 0 20 0 2 0 29369368 224796672 38602 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342656 140417205155403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 169 0 0
/proc/25167/statm: 54882 38602 10359 1052 0 30219 0
[pid=25167/tid=25172] ppid=25166 vsize=219528 CPUtime=7.42
/proc/25167/task/25172/stat : 25172 (aptitude) R 25166 25167 17863 34816 17863 4202560 21290 2201 0 6 732 10 0 0 20 0 2 0 29369621 224796672 38602 18446744073709551615 140417236410368 140417240717720 140736049350896 140417124081384 140417231234169 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.89
Current children cumulated vsize (KiB) 219528

[startup+25.5003 s]
/proc/loadavg: 1.13 1.09 1.03 2/57 25173
/proc/meminfo: memFree=651244/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=356700 CPUtime=23.62
/proc/25167/stat : 25167 (aptitude) S 25166 25167 17863 34816 17863 4202496 61484 2201 78 6 2316 46 0 0 20 0 2 0 29369368 365260800 56492 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342656 140417205155403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 169 0 0
/proc/25167/statm: 89175 56492 10360 1052 0 64512 0
[pid=25167/tid=25172] ppid=25166 vsize=356700 CPUtime=20.16
/proc/25167/task/25172/stat : 25172 (aptitude) R 25166 25167 17863 34816 17863 4202560 39573 2201 0 6 1994 22 0 0 20 0 2 0 29369621 365260800 56492 18446744073709551615 140417236410368 140417240717720 140736049350896 140417124079080 140417238038705 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.62
Current children cumulated vsize (KiB) 356700

[startup+51.1003 s]
/proc/loadavg: 1.08 1.08 1.03 2/57 25173
/proc/meminfo: memFree=512984/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=495592 CPUtime=49.11
/proc/25167/stat : 25167 (aptitude) S 25166 25167 17863 34816 17863 4202496 96701 2201 78 6 4845 66 0 0 20 0 2 0 29369368 507486208 91219 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342656 140417205155403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 169 0 0
/proc/25167/statm: 123898 91219 10360 1052 0 99235 0
[pid=25167/tid=25172] ppid=25166 vsize=495592 CPUtime=45.64
/proc/25167/task/25172/stat : 25172 (aptitude) R 25166 25167 17863 34816 17863 4202560 74790 2201 0 6 4523 41 0 0 20 0 2 0 29369621 507486208 91219 18446744073709551615 140417236410368 140417240717720 140736049350896 140417124082392 140417193920648 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 49.11
Current children cumulated vsize (KiB) 495592

[startup+102.3 s]
/proc/loadavg: 1.03 1.07 1.02 2/57 25173
/proc/meminfo: memFree=149168/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=857440 CPUtime=100.08
/proc/25167/stat : 25167 (aptitude) S 25166 25167 17863 34816 17863 4202496 187068 2201 78 6 9899 109 0 0 20 0 2 0 29369368 878018560 181512 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342656 140417205155403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 169 0 0
/proc/25167/statm: 214360 181512 10375 1052 0 189697 0
[pid=25167/tid=25172] ppid=25166 vsize=857440 CPUtime=96.6
/proc/25167/task/25172/stat : 25172 (aptitude) R 25166 25167 17863 34816 17863 4202560 165151 2201 0 6 9576 84 0 0 20 0 2 0 29369621 878018560 181512 18446744073709551615 140417236410368 140417240717720 140736049350896 140417124079480 140417205146033 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 100.08
Current children cumulated vsize (KiB) 857440



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+150 s]
/proc/loadavg: 1.22 1.10 1.04 2/57 25173
/proc/meminfo: memFree=9272/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=1151640 CPUtime=146.27
/proc/25167/stat : 25167 (aptitude) S 25166 25167 17863 34816 17863 4202496 260690 2201 107 6 14482 145 0 0 20 0 2 0 29369368 1179279360 243802 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342656 140417205155403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 169 0 0
/proc/25167/statm: 287910 243802 10354 1052 0 263247 0
[pid=25167/tid=25172] ppid=25166 vsize=1151640 CPUtime=142.8
/proc/25167/task/25172/stat : 25172 (aptitude) R 25166 25167 17863 34816 17863 4202560 238773 2201 29 6 14159 121 0 0 20 0 2 0 29369621 1179279360 243802 18446744073709551615 140417236410368 140417240717720 140736049350896 140417124079176 140417238621277 0 134217728 4096 0 0 0 0 -1 0 0 0 84 0 0
Current children cumulated CPU time (s) 146.27
Current children cumulated vsize (KiB) 1151640

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

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

[startup+150 s]
/proc/loadavg: 1.22 1.10 1.04 2/57 25173
/proc/meminfo: memFree=9272/1022884 swapFree=0/0
[pid=25167] ppid=25166 vsize=1151640 CPUtime=146.27
/proc/25167/stat : 25167 (aptitude) S 25166 25167 17863 34816 17863 4202496 260690 2201 107 6 14482 145 0 0 20 0 2 0 29369368 1179279360 243802 18446744073709551615 140417236410368 140417240717720 140736049350896 140736049342656 140417205155403 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 169 0 0
/proc/25167/statm: 287910 243802 10354 1052 0 263247 0
[pid=25167/tid=25172] ppid=25166 vsize=1151640 CPUtime=142.8
/proc/25167/task/25172/stat : 25172 (aptitude) R 25166 25167 17863 34816 17863 4202560 238773 2201 29 6 14159 121 0 0 20 0 2 0 29369621 1179279360 243802 18446744073709551615 140417236410368 140417240717720 140736049350896 140417124079176 140417238621277 0 134217728 4096 0 0 0 0 -1 0 0 0 84 0 0
Current children cumulated CPU time (s) 146.27
Current children cumulated vsize (KiB) 1151640

Child ended because it received signal 15 (SIGTERM)
Real time (s): 150.096
CPU time (s): 146.381
CPU user time (s): 144.853
CPU system time (s): 1.52809
CPU usage (%): 97.525
Max. virtual memory (cumulated for all children) (KiB): 1151640

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 144.853
system time used= 1.52809
maximum resident set size= 976896
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262892
page faults= 113
swaps= 0
block input operations= 238920
block output operations= 80
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2570
involuntary context switches= 3374

runsolver used 0.576036 second user time and 0.124007 second system time

The end