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/46.runsolver.aptitude aptitude -s -y --without-recommends install gtkguitune libwrap-ruby1.8 t1lib-bin tct libdb3-util 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.17 1.13 1.06 2/55 25616 /proc/meminfo: memFree=961628/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=3152 CPUtime=0 /proc/25616/stat : 25616 (runsolver) R 25615 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29521684 3227648 33 18446744073709551615 134512640 134586868 4294280384 4294278432 4151735344 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25616/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.178528 s] /proc/loadavg: 1.17 1.13 1.06 2/55 25616 /proc/meminfo: memFree=961628/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=12328 CPUtime=0 /proc/25616/stat : 25616 (aptitude) D 25615 25616 17863 34816 17863 4202496 132 0 7 0 0 0 0 0 20 0 1 0 29521684 12623872 54 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495645448 140083772957239 0 0 0 0 0 0 0 17 0 0 0 16 0 0 /proc/25616/statm: 3082 54 38 1052 0 30 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 12328 [startup+0.200467 s] /proc/loadavg: 1.17 1.13 1.06 2/55 25616 /proc/meminfo: memFree=961628/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=19848 CPUtime=0 /proc/25616/stat : 25616 (aptitude) D 25615 25616 17863 34816 17863 4202496 143 0 11 0 0 0 0 0 20 0 1 0 29521684 20324352 67 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495645304 140083772957239 0 0 0 0 0 0 0 17 0 0 0 19 0 0 /proc/25616/statm: 4962 67 45 1052 0 31 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 19848 [startup+0.300383 s] /proc/loadavg: 1.17 1.13 1.06 2/55 25616 /proc/meminfo: memFree=961628/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=36128 CPUtime=0 /proc/25616/stat : 25616 (aptitude) D 25615 25616 17863 34816 17863 4202496 163 0 19 0 0 0 0 0 20 0 1 0 29521684 36995072 91 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495644424 140083772962182 0 0 0 0 0 0 0 17 0 0 0 28 0 0 /proc/25616/statm: 9032 91 58 1052 0 39 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 36128 [startup+0.7003 s] /proc/loadavg: 1.17 1.13 1.06 2/55 25616 /proc/meminfo: memFree=961628/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=54968 CPUtime=0.01 /proc/25616/stat : 25616 (aptitude) D 25615 25616 17863 34816 17863 4202496 1042 0 66 0 0 1 0 0 20 0 1 0 29521684 56287232 998 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495643160 140083743859056 0 134217728 4096 0 0 0 0 17 0 0 0 67 0 0 /proc/25616/statm: 13742 998 828 1052 0 106 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 54968 [startup+1.50034 s] /proc/loadavg: 1.17 1.13 1.06 1/56 25620 /proc/meminfo: memFree=947228/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=103288 CPUtime=0.03 /proc/25616/stat : 25616 (aptitude) D 25615 25616 17863 34816 17863 4202496 2906 1705 173 4 0 2 0 1 20 0 1 0 29521684 105766912 2879 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495639472 140083770152858 0 134217728 4096 0 0 0 0 17 0 0 0 140 0 0 /proc/25616/statm: 25822 2879 1667 1052 0 1159 0 Current children cumulated CPU time (s) 0.03 Current children cumulated vsize (KiB) 103288 [startup+3.10021 s] /proc/loadavg: 1.17 1.13 1.06 1/56 25620 /proc/meminfo: memFree=944252/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=123068 CPUtime=0.59 /proc/25616/stat : 25616 (aptitude) D 25615 25616 17863 34816 17863 4202496 17368 1705 313 4 50 8 0 1 20 0 1 0 29521684 126021632 15957 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495637432 140083743859056 0 134217728 4096 0 0 0 0 17 0 0 0 246 0 0 /proc/25616/statm: 30767 15957 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.59 Current children cumulated vsize (KiB) 123068 heavy processes: [startup+6.30023 s] /proc/loadavg: 1.15 1.13 1.06 2/57 25621 /proc/meminfo: memFree=796304/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=137832 CPUtime=3.12 /proc/25616/stat : 25616 (aptitude) R 25615 25616 17863 34816 17863 4202496 21696 2203 318 5 293 18 0 1 20 0 2 0 29521684 141139968 17931 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495634704 140083778158131 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/25616/statm: 34458 17931 10303 1052 0 9795 0 [pid=25616/tid=25621] ppid=25615 vsize=137832 CPUtime=0.01 /proc/25616/task/25621/stat : 25621 (aptitude) S 25615 25616 17863 34816 17863 4202560 6 2203 0 5 0 0 0 1 20 0 2 0 29522070 141139968 17931 18446744073709551615 140083775102976 140083779410328 140733495648000 140083662780416 140083743847124 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.12 Current children cumulated vsize (KiB) 137832 heavy processes: [startup+12.7003 s] /proc/loadavg: 1.14 1.13 1.06 2/57 25622 /proc/meminfo: memFree=724500/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=277868 CPUtime=9.49 /proc/25616/stat : 25616 (aptitude) S 25615 25616 17863 34816 17863 4202496 41149 2203 318 5 920 28 0 1 20 0 2 0 29521684 284536832 36779 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495639760 140083743848011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/25616/statm: 69467 36779 10359 1052 0 44804 0 [pid=25616/tid=25621] ppid=25615 vsize=277868 CPUtime=6 /proc/25616/task/25621/stat : 25621 (aptitude) R 25615 25616 17863 34816 17863 4202560 19448 2203 0 5 589 10 0 1 20 0 2 0 29522070 284536832 36779 18446744073709551615 140083775102976 140083779410328 140733495648000 140083662773944 140083777717695 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 9.49 Current children cumulated vsize (KiB) 277868 heavy processes: [startup+25.5003 s] /proc/loadavg: 1.11 1.12 1.06 2/57 25622 /proc/meminfo: memFree=629640/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=369368 CPUtime=22.22 /proc/25616/stat : 25616 (aptitude) S 25615 25616 17863 34816 17863 4202496 64406 2203 318 5 2184 37 0 1 20 0 2 0 29521684 378232832 59681 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495639760 140083743848011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/25616/statm: 92342 59681 10360 1052 0 67679 0 [pid=25616/tid=25621] ppid=25615 vsize=369368 CPUtime=18.73 /proc/25616/task/25621/stat : 25621 (aptitude) R 25615 25616 17863 34816 17863 4202560 42705 2203 0 5 1853 19 0 1 20 0 2 0 29522070 378232832 59681 18446744073709551615 140083775102976 140083779410328 140733495648000 140083662771736 140083777778747 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 22.22 Current children cumulated vsize (KiB) 369368 [startup+51.1002 s] /proc/loadavg: 1.07 1.11 1.06 2/57 25622 /proc/meminfo: memFree=488032/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=512784 CPUtime=47.71 /proc/25616/stat : 25616 (aptitude) S 25615 25616 17863 34816 17863 4202496 100754 2203 318 5 4718 52 0 1 20 0 2 0 29521684 525090816 95528 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495639760 140083743848011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/25616/statm: 128196 95528 10374 1052 0 103533 0 [pid=25616/tid=25621] ppid=25615 vsize=512784 CPUtime=44.21 /proc/25616/task/25621/stat : 25621 (aptitude) R 25615 25616 17863 34816 17863 4202560 79047 2203 0 5 4386 34 0 1 20 0 2 0 29522070 525090816 95528 18446744073709551615 140083775102976 140083779410328 140733495648000 140083662773896 140083776731313 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 47.71 Current children cumulated vsize (KiB) 512784 [startup+102.3 s] /proc/loadavg: 1.03 1.09 1.05 2/57 25622 /proc/meminfo: memFree=77096/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=919504 CPUtime=98.68 /proc/25616/stat : 25616 (aptitude) S 25615 25616 17863 34816 17863 4202496 202365 2203 318 5 9764 103 0 1 20 0 2 0 29521684 941572096 197051 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495639760 140083743848011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/25616/statm: 229876 197051 10375 1052 0 205213 0 [pid=25616/tid=25621] ppid=25615 vsize=919504 CPUtime=95.18 /proc/25616/task/25621/stat : 25621 (aptitude) R 25615 25616 17863 34816 17863 4202560 180658 2203 0 5 9432 85 0 1 20 0 2 0 29522070 941572096 197051 18446744073709551615 140083775102976 140083779410328 140733495648000 140083662770424 140083777749274 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 98.68 Current children cumulated vsize (KiB) 919504 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+128.3 s] /proc/loadavg: 1.17 1.11 1.06 2/57 25622 /proc/meminfo: memFree=9952/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=1151048 CPUtime=123.3 /proc/25616/stat : 25616 (aptitude) S 25615 25616 17863 34816 17863 4202496 260339 2203 370 5 12187 142 0 1 20 0 2 0 29521684 1178673152 244486 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495639760 140083743848011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/25616/statm: 287762 244486 10340 1052 0 263099 0 [pid=25616/tid=25621] ppid=25615 vsize=1151048 CPUtime=119.8 /proc/25616/task/25621/stat : 25621 (aptitude) R 25615 25616 17863 34816 17863 4202560 238632 2203 52 5 11855 124 0 1 20 0 2 0 29522070 1178673152 244486 18446744073709551615 140083775102976 140083779410328 140733495648000 140083662772088 140083777952016 0 134217728 4096 0 0 0 0 -1 0 0 0 86 0 0 Current children cumulated CPU time (s) 123.3 Current children cumulated vsize (KiB) 1151048 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+128.3 s] /proc/loadavg: 1.17 1.11 1.06 2/57 25622 /proc/meminfo: memFree=9952/1022884 swapFree=0/0 [pid=25616] ppid=25615 vsize=1151048 CPUtime=123.3 /proc/25616/stat : 25616 (aptitude) S 25615 25616 17863 34816 17863 4202496 260339 2203 370 5 12187 142 0 1 20 0 2 0 29521684 1178673152 244486 18446744073709551615 140083775102976 140083779410328 140733495648000 140733495639760 140083743848011 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 310 0 0 /proc/25616/statm: 287762 244486 10340 1052 0 263099 0 [pid=25616/tid=25621] ppid=25615 vsize=1151048 CPUtime=119.8 /proc/25616/task/25621/stat : 25621 (aptitude) R 25615 25616 17863 34816 17863 4202560 238632 2203 52 5 11855 124 0 1 20 0 2 0 29522070 1178673152 244486 18446744073709551615 140083775102976 140083779410328 140733495648000 140083662772088 140083777952016 0 134217728 4096 0 0 0 0 -1 0 0 0 86 0 0 Current children cumulated CPU time (s) 123.3 Current children cumulated vsize (KiB) 1151048 Child ended because it received signal 15 (SIGTERM) Real time (s): 128.402 CPU time (s): 123.396 CPU user time (s): 121.888 CPU system time (s): 1.50809 CPU usage (%): 96.1009 Max. virtual memory (cumulated for all children) (KiB): 1151048 getrusage(RUSAGE_CHILDREN,...) data: user time used= 121.888 system time used= 1.50809 maximum resident set size= 981540 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 262569 page faults= 376 swaps= 0 block input operations= 273224 block output operations= 88 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2757 involuntary context switches= 2848 runsolver used 0.16801 second user time and 0.508031 second system time The end