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/29.runsolver.aptitude aptitude -s -y --without-recommends install curl rmagic gnomeicu-common libxml-stream-perl liblablgl-ocaml 

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.22 1.11 1.04 2/55 25231
/proc/meminfo: memFree=960468/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=3152 CPUtime=0
/proc/25231/stat : 25231 (runsolver) R 25230 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29436218 3227648 32 18446744073709551615 134512640 134586868 4287535968 4287534016 4151604272 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/25231/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.151589 s]
/proc/loadavg: 1.22 1.11 1.04 2/55 25231
/proc/meminfo: memFree=960468/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=25980 CPUtime=0
/proc/25231/stat : 25231 (aptitude) D 25230 25231 17863 34816 17863 4202496 147 0 13 0 0 0 0 0 20 0 1 0 29436218 26603520 73 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640562296 139861432779542 0 0 0 0 0 0 0 17 0 0 0 13 0 0
/proc/25231/statm: 6495 73 48 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 25980

[startup+0.200367 s]
/proc/loadavg: 1.22 1.11 1.04 2/55 25231
/proc/meminfo: memFree=960468/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=28716 CPUtime=0
/proc/25231/stat : 25231 (aptitude) D 25230 25231 17863 34816 17863 4202496 152 0 14 0 0 0 0 0 20 0 1 0 29436218 29405184 78 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640562248 139861432780323 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/25231/statm: 7179 78 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.300365 s]
/proc/loadavg: 1.22 1.11 1.04 2/55 25231
/proc/meminfo: memFree=960468/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=40832 CPUtime=0
/proc/25231/stat : 25231 (aptitude) D 25230 25231 17863 34816 17863 4202496 172 0 21 0 0 0 0 0 20 0 1 0 29436218 41811968 101 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640562056 139861432780323 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/25231/statm: 10208 101 63 1052 0 60 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 40832

[startup+0.700333 s]
/proc/loadavg: 1.22 1.11 1.04 2/55 25231
/proc/meminfo: memFree=960468/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=63380 CPUtime=0.01
/proc/25231/stat : 25231 (aptitude) D 25230 25231 17863 34816 17863 4202496 1156 0 62 0 0 1 0 0 20 0 1 0 29436218 64901120 1094 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640561592 139861437844864 0 134217728 4096 0 0 0 0 17 0 0 0 67 0 0
/proc/25231/statm: 15845 1094 915 1052 0 108 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 63380

[startup+1.5002 s]
/proc/loadavg: 1.22 1.11 1.04 2/56 25235
/proc/meminfo: memFree=950036/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=103432 CPUtime=0.3
/proc/25231/stat : 25231 (aptitude) R 25230 25231 17863 34816 17863 4202496 11287 1703 142 4 29 1 0 0 20 0 1 0 29436218 105914368 11220 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640555408 139861429768969 0 134217728 4096 0 0 0 0 17 0 0 0 112 0 0
/proc/25231/statm: 25858 11220 9956 1052 0 1195 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 103432

[startup+3.10022 s]
/proc/loadavg: 1.22 1.11 1.04 1/56 25235
/proc/meminfo: memFree=866460/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=126624 CPUtime=1.18
/proc/25231/stat : 25231 (aptitude) R 25230 25231 17863 34816 17863 4202496 18074 1703 145 4 106 12 0 0 20 0 2 0 29436218 129662976 15139 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640561416 139861429764274 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 185 0 0
/proc/25231/statm: 31656 15139 10141 1052 0 6993 0
Current children cumulated CPU time (s) 1.18
Current children cumulated vsize (KiB) 126624
heavy processes:

[startup+6.30025 s]
/proc/loadavg: 1.20 1.10 1.04 2/57 25237
/proc/meminfo: memFree=797136/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=155516 CPUtime=4.35
/proc/25231/stat : 25231 (aptitude) S 25230 25231 17863 34816 17863 4202496 26614 2200 148 5 414 20 0 1 20 0 2 0 29436218 159248384 22610 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640557392 139861403665995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/25231/statm: 38879 22610 10359 1052 0 14216 0
[pid=25231/tid=25236] ppid=25230 vsize=155516 CPUtime=0.86
/proc/25231/task/25236/stat : 25236 (aptitude) R 25230 25231 17863 34816 17863 4202560 4775 2200 0 5 83 2 0 1 20 0 2 0 29436489 159248384 22610 18446744073709551615 139861434920960 139861439228312 140733640565632 139861322588952 139861403661870 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.35
Current children cumulated vsize (KiB) 155516
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.18 1.10 1.04 2/57 25237
/proc/meminfo: memFree=723232/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=283540 CPUtime=10.71
/proc/25231/stat : 25231 (aptitude) S 25230 25231 17863 34816 17863 4202496 42761 2200 148 5 1040 30 0 1 20 0 2 0 29436218 290344960 38227 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640557392 139861403665995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/25231/statm: 70885 38227 10359 1052 0 46222 0
[pid=25231/tid=25236] ppid=25230 vsize=283540 CPUtime=7.22
/proc/25231/task/25236/stat : 25236 (aptitude) R 25230 25231 17863 34816 17863 4202560 20921 2200 0 5 709 12 0 1 20 0 2 0 29436489 290344960 38227 18446744073709551615 139861434920960 139861439228312 140733640565632 139861322589720 139861401230400 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.71
Current children cumulated vsize (KiB) 283540

[startup+25.5003 s]
/proc/loadavg: 1.14 1.10 1.04 2/57 25237
/proc/meminfo: memFree=641268/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=362652 CPUtime=23.43
/proc/25231/stat : 25231 (aptitude) S 25230 25231 17863 34816 17863 4202496 62902 2200 148 5 2303 39 0 1 20 0 2 0 29436218 371355648 57994 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640557392 139861403665995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/25231/statm: 90663 57994 10360 1052 0 66000 0
[pid=25231/tid=25236] ppid=25230 vsize=362652 CPUtime=19.94
/proc/25231/task/25236/stat : 25236 (aptitude) R 25230 25231 17863 34816 17863 4202560 41062 2200 0 5 1972 21 0 1 20 0 2 0 29436489 371355648 57994 18446744073709551615 139861434920960 139861439228312 140733640565632 139861322592760 139861437545647 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 23.43
Current children cumulated vsize (KiB) 362652

[startup+51.1003 s]
/proc/loadavg: 1.09 1.09 1.04 2/57 25245
/proc/meminfo: memFree=497024/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=504996 CPUtime=48.88
/proc/25231/stat : 25231 (aptitude) S 25230 25231 17863 34816 17863 4202496 98952 2200 148 5 4832 55 0 1 20 0 2 0 29436218 517115904 93553 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640557392 139861403665995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/25231/statm: 126249 93553 10360 1052 0 101586 0
[pid=25231/tid=25236] ppid=25230 vsize=504996 CPUtime=45.39
/proc/25231/task/25236/stat : 25236 (aptitude) R 25230 25231 17863 34816 17863 4202560 77112 2200 0 5 4501 37 0 1 20 0 2 0 29436489 517115904 93553 18446744073709551615 139861434920960 139861439228312 140733640565632 139861322589848 139861437628337 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0
Current children cumulated CPU time (s) 48.88
Current children cumulated vsize (KiB) 504996

[startup+102.3 s]
/proc/loadavg: 1.04 1.07 1.03 2/57 25245
/proc/meminfo: memFree=9208/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=1004460 CPUtime=99.47
/proc/25231/stat : 25231 (aptitude) S 25230 25231 17863 34816 17863 4202496 223795 2200 148 5 9822 124 0 1 20 0 2 0 29436218 1028567040 218301 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640557392 139861403665995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/25231/statm: 251115 218301 10375 1052 0 226452 0
[pid=25231/tid=25236] ppid=25230 vsize=1004460 CPUtime=95.97
/proc/25231/task/25236/stat : 25236 (aptitude) R 25230 25231 17863 34816 17863 4202560 201949 2200 0 5 9490 106 0 1 20 0 2 0 29436489 1028567040 218301 18446744073709551615 139861434920960 139861439228312 140733640565632 139861322588648 139861392421221 0 134217728 4096 0 0 0 0 -1 0 0 0 37 0 0
Current children cumulated CPU time (s) 99.47
Current children cumulated vsize (KiB) 1004460



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+119.103 s]
/proc/loadavg: 1.09 1.08 1.04 2/57 25245
/proc/meminfo: memFree=10048/1022884 swapFree=0/0
[pid=25231] ppid=25230 vsize=1151540 CPUtime=115.59
/proc/25231/stat : 25231 (aptitude) S 25230 25231 17863 34816 17863 4202496 260636 2200 178 5 11408 150 0 1 20 0 2 0 29436218 1179176960 244255 18446744073709551615 139861434920960 139861439228312 140733640565632 140733640557392 139861403665995 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 187 0 0
/proc/25231/statm: 287885 244255 10337 1052 0 263222 0
[pid=25231/tid=25236] ppid=25230 vsize=1151540 CPUtime=112.1
/proc/25231/task/25236/stat : 25236 (aptitude) R 25230 25231 17863 34816 17863 4202560 238781 2200 27 5 11076 133 0 1 20 0 2 0 29436489 1179176960 244255 18446744073709551615 139861434920960 139861439228312 140733640565632 139861322590072 139861437812115 0 134217728 4096 0 0 0 0 -1 0 0 0 57 0 0
Current children cumulated CPU time (s) 115.59
Current children cumulated vsize (KiB) 1151540

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.204
CPU time (s): 115.699
CPU user time (s): 114.107
CPU system time (s): 1.5921
CPU usage (%): 97.0595
Max. virtual memory (cumulated for all children) (KiB): 1151540

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 114.107
system time used= 1.5921
maximum resident set size= 978984
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262884
page faults= 183
swaps= 0
block input operations= 258848
block output operations= 88
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2576
involuntary context switches= 2775

runsolver used 0.156009 second user time and 0.404025 second system time

The end