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/68.runsolver.aptitude aptitude -s -y --without-recommends install freecraft smartlist php3 sendxmpp inetutils-talk 

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.43 1.16 1.07 2/55 26048
/proc/meminfo: memFree=750036/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=3152 CPUtime=0
/proc/26048/stat : 26048 (runsolver) R 26047 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29663137 3227648 32 18446744073709551615 134512640 134586868 4288077664 4288075712 4151948336 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.20508 s]
/proc/loadavg: 1.43 1.16 1.07 2/55 26048
/proc/meminfo: memFree=750036/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=103288 CPUtime=0.2
/proc/26048/stat : 26048 (aptitude) R 26047 26048 17863 34816 17863 4202496 11302 1709 0 0 15 4 1 0 20 0 1 0 29663137 105766912 11103 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031056 139949591251438 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 25822 11103 9891 1052 0 1159 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 103288

[startup+0.300343 s]
/proc/loadavg: 1.43 1.16 1.07 2/55 26048
/proc/meminfo: memFree=750036/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=103432 CPUtime=0.3
/proc/26048/stat : 26048 (aptitude) R 26047 26048 17863 34816 17863 4202496 11427 1709 0 0 25 4 1 0 20 0 1 0 29663137 105914368 11220 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360029568 139949591263202 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 103432

[startup+0.400243 s]
/proc/loadavg: 1.43 1.16 1.07 2/55 26048
/proc/meminfo: memFree=750036/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=114256 CPUtime=0.39
/proc/26048/stat : 26048 (aptitude) R 26047 26048 17863 34816 17863 4202496 14145 1709 0 0 34 4 1 0 20 0 1 0 29663137 116998144 13937 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360028936 139949598534813 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 28564 13937 9967 1052 0 3901 0
Current children cumulated CPU time (s) 0.39
Current children cumulated vsize (KiB) 114256

[startup+0.700204 s]
/proc/loadavg: 1.43 1.16 1.07 2/55 26048
/proc/meminfo: memFree=750036/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=123068 CPUtime=0.69
/proc/26048/stat : 26048 (aptitude) R 26047 26048 17863 34816 17863 4202496 17688 1709 0 0 61 7 1 0 20 0 1 0 29663137 126021632 15965 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360029224 139949591310490 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 30767 15965 9976 1052 0 6104 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 123068

[startup+1.50024 s]
/proc/loadavg: 1.39 1.15 1.07 2/57 26053
/proc/meminfo: memFree=729940/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=136068 CPUtime=1.48
/proc/26048/stat : 26048 (aptitude) R 26047 26048 17863 34816 17863 4202496 20646 1709 0 0 139 8 1 0 20 0 2 0 29663137 139333632 17565 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031064 139949553991584 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 34017 17565 10207 1052 0 9354 0
[pid=26048/tid=26053] ppid=26047 vsize=136068 CPUtime=0.01
/proc/26048/task/26053/stat : 26053 (aptitude) S 26047 26048 17863 34816 17863 4202560 4 1709 0 0 0 0 1 0 20 0 2 0 29663215 139333632 17565 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484087296 139949565154004 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) 136068

[startup+3.10023 s]
/proc/loadavg: 1.39 1.15 1.07 2/57 26053
/proc/meminfo: memFree=719772/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=137824 CPUtime=3.07
/proc/26048/stat : 26048 (aptitude) R 26047 26048 17863 34816 17863 4202496 21993 2208 0 0 292 14 1 0 20 0 2 0 29663137 141131776 17934 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360026496 139949599400972 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 34456 17934 10303 1052 0 9793 0
[pid=26048/tid=26053] ppid=26047 vsize=137824 CPUtime=0.01
/proc/26048/task/26053/stat : 26053 (aptitude) S 26047 26048 17863 34816 17863 4202560 6 2208 0 0 0 0 1 0 20 0 2 0 29663215 141131776 17934 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484087296 139949565154004 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 137824

[startup+6.30023 s]
/proc/loadavg: 1.39 1.15 1.07 2/57 26054
/proc/meminfo: memFree=677612/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=250772 CPUtime=6.26
/proc/26048/stat : 26048 (aptitude) S 26047 26048 17863 34816 17863 4202496 34662 2208 0 0 604 21 1 0 20 0 2 0 29663137 256790528 30045 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031552 139949565154891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 62693 30045 10359 1052 0 38030 0
[pid=26048/tid=26053] ppid=26047 vsize=250772 CPUtime=2.83
/proc/26048/task/26053/stat : 26053 (aptitude) R 26047 26048 17863 34816 17863 4202560 12668 2208 0 0 275 7 1 0 20 0 2 0 29663215 256790528 30045 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484080824 139949553913396 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.26
Current children cumulated vsize (KiB) 250772

[startup+12.7002 s]
/proc/loadavg: 1.33 1.15 1.07 2/57 26054
/proc/meminfo: memFree=628384/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=296116 CPUtime=12.63
/proc/26048/stat : 26048 (aptitude) S 26047 26048 17863 34816 17863 4202496 46157 2208 0 0 1236 26 1 0 20 0 2 0 29663137 303222784 41354 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031552 139949565154891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 74029 41354 10360 1052 0 49366 0
[pid=26048/tid=26053] ppid=26047 vsize=296116 CPUtime=9.2
/proc/26048/task/26053/stat : 26053 (aptitude) R 26047 26048 17863 34816 17863 4202560 24163 2208 0 0 907 12 1 0 20 0 2 0 29663215 303222784 41354 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484080224 139949591233657 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 296116

[startup+25.5033 s]
/proc/loadavg: 1.28 1.14 1.07 2/57 26054
/proc/meminfo: memFree=550264/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=371416 CPUtime=25.37
/proc/26048/stat : 26048 (aptitude) S 26047 26048 17863 34816 17863 4202496 65648 2208 0 0 2499 37 1 0 20 0 2 0 29663137 380329984 60174 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031552 139949565154891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 92854 60174 10360 1052 0 68191 0
[pid=26048/tid=26053] ppid=26047 vsize=371416 CPUtime=21.94
/proc/26048/task/26053/stat : 26053 (aptitude) R 26047 26048 17863 34816 17863 4202560 43654 2208 0 0 2170 23 1 0 20 0 2 0 29663215 380329984 60174 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484078568 139949598038193 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 25.37
Current children cumulated vsize (KiB) 371416

[startup+51.1002 s]
/proc/loadavg: 1.18 1.13 1.06 2/57 26054
/proc/meminfo: memFree=375052/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=547732 CPUtime=50.85
/proc/26048/stat : 26048 (aptitude) S 26047 26048 17863 34816 17863 4202496 109868 2208 0 0 5026 58 1 0 20 0 2 0 29663137 560877568 104251 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031552 139949565154891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 136933 104251 10360 1052 0 112270 0
[pid=26048/tid=26053] ppid=26047 vsize=547732 CPUtime=47.42
/proc/26048/task/26053/stat : 26053 (aptitude) R 26047 26048 17863 34816 17863 4202560 87874 2208 0 0 4697 44 1 0 20 0 2 0 29663215 560877568 104251 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484078568 139949591233657 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.85
Current children cumulated vsize (KiB) 547732

[startup+102.3 s]
/proc/loadavg: 1.23 1.14 1.07 2/57 26054
/proc/meminfo: memFree=8352/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=992180 CPUtime=99.18
/proc/26048/stat : 26048 (aptitude) S 26047 26048 17863 34816 17863 4202496 220872 2208 45 0 9793 124 1 0 20 0 2 0 29663137 1015992320 214012 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031552 139949565154891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 248045 214012 9179 1052 0 223382 0
[pid=26048/tid=26053] ppid=26047 vsize=992180 CPUtime=95.75
/proc/26048/task/26053/stat : 26053 (aptitude) R 26047 26048 17863 34816 17863 4202560 198872 2208 45 0 9464 110 1 0 20 0 2 0 29663215 1015992320 214012 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484080728 139949599124701 0 134217728 4096 0 0 0 0 -1 0 0 0 253 0 0
Current children cumulated CPU time (s) 99.18
Current children cumulated vsize (KiB) 992180



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+119.3 s]
/proc/loadavg: 1.24 1.15 1.07 2/57 26054
/proc/meminfo: memFree=8968/1022884 swapFree=0/0
[pid=26048] ppid=26047 vsize=1151340 CPUtime=114.95
/proc/26048/stat : 26048 (aptitude) S 26047 26048 17863 34816 17863 4202496 260724 2208 130 0 11342 152 1 0 20 0 2 0 29663137 1178972160 234940 18446744073709551615 139949596409856 139949600717208 140734360039792 140734360031552 139949565154891 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/26048/statm: 287835 234940 8008 1052 0 263172 0
[pid=26048/tid=26053] ppid=26047 vsize=1151340 CPUtime=111.52
/proc/26048/task/26053/stat : 26053 (aptitude) R 26047 26048 17863 34816 17863 4202560 238724 2208 130 0 11013 138 1 0 20 0 2 0 29663215 1178972160 234940 18446744073709551615 139949596409856 139949600717208 140734360039792 139949484077688 139949562723264 0 134217728 4096 0 0 0 0 -1 0 0 0 332 0 0
Current children cumulated CPU time (s) 114.95
Current children cumulated vsize (KiB) 1151340

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

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

Child ended because it received signal 15 (SIGTERM)
Real time (s): 119.559
CPU time (s): 115.127
CPU user time (s): 113.523
CPU system time (s): 1.6041
CPU usage (%): 96.2932
Max. virtual memory (cumulated for all children) (KiB): 1151340

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 113.523
system time used= 1.6041
maximum resident set size= 941720
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 263158
page faults= 130
swaps= 0
block input operations= 6872
block output operations= 88
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 482
involuntary context switches= 3268

runsolver used 0.108006 second user time and 0.516032 second system time

The end