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/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.05 1.05 1.01 2/55 23162
/proc/meminfo: memFree=961972/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=3152 CPUtime=0
/proc/23162/stat : 23162 (runsolver) R 23161 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28848645 3227648 33 18446744073709551615 134512640 134586868 4292470992 4292469040 4151989296 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/23162/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.138733 s]
/proc/loadavg: 1.05 1.05 1.01 2/55 23162
/proc/meminfo: memFree=961972/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=4628 CPUtime=0
/proc/23162/stat : 23162 (aptitude) D 23161 23162 17863 34816 17863 4202496 115 0 3 0 0 0 0 0 20 0 1 0 28848645 4739072 36 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519836120 140676420178391 0 0 0 0 0 0 0 17 0 0 0 11 0 0
/proc/23162/statm: 1157 36 28 1052 0 29 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 4628

[startup+0.200432 s]
/proc/loadavg: 1.05 1.05 1.01 2/55 23162
/proc/meminfo: memFree=961972/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=12328 CPUtime=0
/proc/23162/stat : 23162 (aptitude) D 23161 23162 17863 34816 17863 4202496 129 0 5 0 0 0 0 0 20 0 1 0 28848645 12623872 50 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519835432 140676420183587 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/23162/statm: 3082 50 36 1052 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 12328

[startup+0.300399 s]
/proc/loadavg: 1.05 1.05 1.01 2/55 23162
/proc/meminfo: memFree=961972/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=28716 CPUtime=0
/proc/23162/stat : 23162 (aptitude) D 23161 23162 17863 34816 17863 4202496 155 0 11 0 0 0 0 0 20 0 1 0 28848645 29405184 77 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519835144 140676420183587 0 0 0 0 0 0 0 17 0 0 0 28 0 0
/proc/23162/statm: 7179 77 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.700314 s]
/proc/loadavg: 1.05 1.05 1.01 2/55 23162
/proc/meminfo: memFree=961972/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=63384 CPUtime=0.01
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 1213 0 30 0 0 1 0 0 20 0 1 0 28848645 64905216 1108 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519829576 140676380169968 0 134217728 4096 0 0 0 0 17 0 0 0 68 0 0
/proc/23162/statm: 15846 1108 929 1052 0 109 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 63384

[startup+1.5002 s]
/proc/loadavg: 1.05 1.05 1.01 1/56 23166
/proc/meminfo: memFree=954516/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=100508 CPUtime=0.06
/proc/23162/stat : 23162 (aptitude) R 23161 23162 17863 34816 17863 4202496 8529 1704 154 4 4 2 0 0 20 0 1 0 28848645 102920192 8484 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519829792 140676417724978 0 134217728 4096 0 0 0 0 17 0 0 0 137 0 0
/proc/23162/statm: 25127 8484 7309 1052 0 1122 0
Current children cumulated CPU time (s) 0.06
Current children cumulated vsize (KiB) 100508

[startup+3.10022 s]
/proc/loadavg: 1.05 1.05 1.01 2/56 23166
/proc/meminfo: memFree=912976/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=123288 CPUtime=0.99
/proc/23162/stat : 23162 (aptitude) R 23161 23162 17863 34816 17863 4202496 16861 1704 169 4 87 12 0 0 20 0 2 0 28848645 126246912 14303 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519834312 140676417057157 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 204 0 0
/proc/23162/statm: 30822 14303 9482 1052 0 6817 0
Current children cumulated CPU time (s) 0.99
Current children cumulated vsize (KiB) 123288
heavy processes:

[startup+6.3003 s]
/proc/loadavg: 1.04 1.05 1.01 2/57 23168
/proc/meminfo: memFree=833608/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=220756 CPUtime=4.13
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 26104 2200 169 6 392 21 0 0 20 0 2 0 28848645 226054144 22528 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519830288 140676391069259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 205 0 0
/proc/23162/statm: 55189 22528 9700 1052 0 31184 0
[pid=23162/tid=23167] ppid=23161 vsize=220756 CPUtime=0.98
/proc/23162/task/23167/stat : 23167 (aptitude) R 23161 23162 17863 34816 17863 4202560 5661 2200 0 6 96 2 0 0 20 0 2 0 28848924 226054144 22528 18446744073709551615 140676422324224 140676426631576 140733519838528 140676313142424 140676424967096 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.13
Current children cumulated vsize (KiB) 220756
heavy processes:

[startup+12.7003 s]
/proc/loadavg: 1.04 1.05 1.01 2/57 23168
/proc/meminfo: memFree=768260/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=276500 CPUtime=10.49
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 40868 2200 169 6 1019 30 0 0 20 0 2 0 28848645 283136000 36464 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519830288 140676391069259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 205 0 0
/proc/23162/statm: 69125 36464 9700 1052 0 45120 0
[pid=23162/tid=23167] ppid=23161 vsize=276500 CPUtime=7.35
/proc/23162/task/23167/stat : 23167 (aptitude) R 23161 23162 17863 34816 17863 4202560 20425 2200 0 6 723 12 0 0 20 0 2 0 28848924 283136000 36464 18446744073709551615 140676422324224 140676426631576 140733519838528 140676313144968 140676423674387 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.49
Current children cumulated vsize (KiB) 276500

[startup+25.5003 s]
/proc/loadavg: 1.03 1.05 1.00 2/57 23168
/proc/meminfo: memFree=657280/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=384192 CPUtime=23.23
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 68180 2200 169 6 2282 41 0 0 20 0 2 0 28848645 393412608 63323 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519830288 140676391069259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 205 0 0
/proc/23162/statm: 96048 63323 9700 1052 0 72043 0
[pid=23162/tid=23167] ppid=23161 vsize=384192 CPUtime=20.08
/proc/23162/task/23167/stat : 23167 (aptitude) R 23161 23162 17863 34816 17863 4202560 47737 2200 0 6 1986 22 0 0 20 0 2 0 28848924 393412608 63323 18446744073709551615 140676422324224 140676426631576 140733519838528 140676313144920 140676424894868 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 23.23
Current children cumulated vsize (KiB) 384192

[startup+51.1003 s]
/proc/loadavg: 1.02 1.04 1.00 2/57 23168
/proc/meminfo: memFree=456276/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=587164 CPUtime=48.68
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 118988 2200 169 6 4804 64 0 0 20 0 2 0 28848645 601255936 114052 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519830288 140676391069259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 205 0 0
/proc/23162/statm: 146791 114052 9716 1052 0 122786 0
[pid=23162/tid=23167] ppid=23161 vsize=587164 CPUtime=45.54
/proc/23162/task/23167/stat : 23167 (aptitude) R 23161 23162 17863 34816 17863 4202560 98539 2200 0 6 4508 46 0 0 20 0 2 0 28848924 601255936 114052 18446744073709551615 140676422324224 140676426631576 140733519838528 140676313145736 140676424994402 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0
Current children cumulated CPU time (s) 48.68
Current children cumulated vsize (KiB) 587164

[startup+102.3 s]
/proc/loadavg: 1.01 1.03 1.00 2/57 23168
/proc/meminfo: memFree=8480/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=1033564 CPUtime=99.02
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 230507 2200 169 6 9771 131 0 0 20 0 2 0 28848645 1058369536 225571 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519830288 140676391069259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 205 0 0
/proc/23162/statm: 258391 225571 9716 1052 0 234386 0
[pid=23162/tid=23167] ppid=23161 vsize=1033564 CPUtime=95.86
/proc/23162/task/23167/stat : 23167 (aptitude) D 23161 23162 17863 34816 17863 4204608 210058 2200 0 6 9474 112 0 0 20 0 2 0 28848924 1058369536 225571 18446744073709551615 140676422324224 140676426631576 140733519838528 140676313142856 140676379827658 0 134217728 4096 0 0 0 0 -1 0 0 0 70 0 0
Current children cumulated CPU time (s) 99.02
Current children cumulated vsize (KiB) 1033564



Maximum VSize exceeded: sending signal-name then SIGKILL

[startup+117.1 s]
/proc/loadavg: 1.15 1.06 1.01 3/57 23168
/proc/meminfo: memFree=9484/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=1151308 CPUtime=112.88
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 260031 2200 222 6 11134 154 0 0 20 0 2 0 28848645 1178939392 244823 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519830288 140676391069259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 206 0 0
/proc/23162/statm: 287827 244823 9651 1052 0 263822 0
[pid=23162/tid=23167] ppid=23161 vsize=1151308 CPUtime=109.72
/proc/23162/task/23167/stat : 23167 (aptitude) R 23161 23162 17863 34816 17863 4202560 239571 2200 48 6 10837 135 0 0 20 0 2 0 28848924 1178939392 244823 18446744073709551615 140676422324224 140676426631576 140733519838528 140676313145624 140676424535130 0 134217728 4096 0 0 0 0 -1 0 0 0 109 0 0
Current children cumulated CPU time (s) 112.88
Current children cumulated vsize (KiB) 1151308

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

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

[startup+117.1 s]
/proc/loadavg: 1.15 1.06 1.01 3/57 23168
/proc/meminfo: memFree=9484/1022884 swapFree=0/0
[pid=23162] ppid=23161 vsize=1151308 CPUtime=112.88
/proc/23162/stat : 23162 (aptitude) S 23161 23162 17863 34816 17863 4202496 260031 2200 222 6 11134 154 0 0 20 0 2 0 28848645 1178939392 244823 18446744073709551615 140676422324224 140676426631576 140733519838528 140733519830288 140676391069259 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 206 0 0
/proc/23162/statm: 287827 244823 9651 1052 0 263822 0
[pid=23162/tid=23167] ppid=23161 vsize=1151308 CPUtime=109.72
/proc/23162/task/23167/stat : 23167 (aptitude) R 23161 23162 17863 34816 17863 4202560 239571 2200 48 6 10837 135 0 0 20 0 2 0 28848924 1178939392 244823 18446744073709551615 140676422324224 140676426631576 140733519838528 140676313145624 140676424535130 0 134217728 4096 0 0 0 0 -1 0 0 0 109 0 0
Current children cumulated CPU time (s) 112.88
Current children cumulated vsize (KiB) 1151308

Child ended because it received signal 15 (SIGTERM)
Real time (s): 117.225
CPU time (s): 112.999
CPU user time (s): 111.379
CPU system time (s): 1.6201
CPU usage (%): 96.3946
Max. virtual memory (cumulated for all children) (KiB): 1151308

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 111.379
system time used= 1.6201
maximum resident set size= 980632
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 262268
page faults= 229
swaps= 0
block input operations= 187184
block output operations= 88
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 2097
involuntary context switches= 2540

runsolver used 0.212013 second user time and 0.392024 second system time

The end