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/logs/129.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config remove kgamma gnome cron libksieve0 libsm-dev 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: 0.91 0.95 0.93 2/53 8336 /proc/meminfo: memFree=447660/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=3152 CPUtime=0 /proc/8336/stat : 8336 (runsolver) R 8335 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 3899749 3227648 33 18446744073709551615 134512640 134586868 4294685088 4294683136 4151743536 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.144426 s] /proc/loadavg: 0.91 0.95 0.93 2/53 8336 /proc/meminfo: memFree=447660/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=113400 CPUtime=0.13 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 9687 413 0 0 10 3 0 0 20 0 1 0 3899749 116121600 6107 18446744073709551615 4194304 6763684 140734296039408 140734296035400 5511976 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 28350 6107 1058 628 0 4903 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 113400 [startup+0.200239 s] /proc/loadavg: 0.91 0.95 0.93 2/53 8336 /proc/meminfo: memFree=447660/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=120164 CPUtime=0.19 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 13565 413 0 0 16 3 0 0 20 0 1 0 3899749 123047936 7786 18446744073709551615 4194304 6763684 140734296039408 140734296035464 140537933863355 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 30041 7786 1058 628 0 6594 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 120164 [startup+0.300242 s] /proc/loadavg: 0.91 0.95 0.93 2/53 8336 /proc/meminfo: memFree=447660/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=134452 CPUtime=0.28 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 17151 413 0 0 25 3 0 0 20 0 1 0 3899749 137678848 11368 18446744073709551615 4194304 6763684 140734296039408 140734296035400 140537952798402 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 33613 11368 1059 628 0 10166 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 134452 [startup+0.700181 s] /proc/loadavg: 0.91 0.95 0.93 2/53 8336 /proc/meminfo: memFree=447660/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=196064 CPUtime=0.68 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 35618 413 0 0 60 8 0 0 20 0 1 0 3899749 200769536 26749 18446744073709551615 4194304 6763684 140734296039408 140734296035400 140537916820030 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 49016 26749 1059 628 0 25569 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 196064 [startup+1.5002 s] /proc/loadavg: 0.91 0.95 0.93 2/54 8339 /proc/meminfo: memFree=334440/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=207776 CPUtime=1.48 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 44754 413 0 0 138 10 0 0 20 0 1 0 3899749 212762624 29707 18446744073709551615 4194304 6763684 140734296039408 140734296034544 4926653 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 51944 29707 1069 628 0 28497 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 207776 [startup+3.10018 s] /proc/loadavg: 0.91 0.95 0.93 2/54 8339 /proc/meminfo: memFree=332828/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=207776 CPUtime=3.07 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 44766 413 0 0 297 10 0 0 20 0 1 0 3899749 212762624 29710 18446744073709551615 4194304 6763684 140734296039408 140734296036360 140537934552794 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 207776 [startup+6.30018 s] /proc/loadavg: 0.92 0.95 0.93 2/54 8339 /proc/meminfo: memFree=332572/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=207776 CPUtime=6.26 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 44766 413 0 0 616 10 0 0 20 0 1 0 3899749 212762624 29710 18446744073709551615 4194304 6763684 140734296039408 140734296036360 140537934552794 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 207776 [startup+12.7002 s] /proc/loadavg: 0.93 0.95 0.93 2/54 8339 /proc/meminfo: memFree=332448/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=207776 CPUtime=12.64 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 44766 413 0 0 1254 10 0 0 20 0 1 0 3899749 212762624 29710 18446744073709551615 4194304 6763684 140734296039408 140734296036360 140537916804801 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 207776 [startup+25.5002 s] /proc/loadavg: 0.94 0.96 0.93 2/54 8339 /proc/meminfo: memFree=332448/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=207776 CPUtime=25.39 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 44766 413 0 0 2529 10 0 0 20 0 1 0 3899749 212762624 29710 18446744073709551615 4194304 6763684 140734296039408 140734296036360 140537916804801 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 51944 29710 1072 628 0 28497 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 207776 [startup+51.1002 s] /proc/loadavg: 0.96 0.96 0.93 2/54 8339 /proc/meminfo: memFree=332448/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=207776 CPUtime=50.9 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 44767 413 0 0 5080 10 0 0 20 0 1 0 3899749 212762624 29711 18446744073709551615 4194304 6763684 140734296039408 140734296036360 140537934552928 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 51944 29711 1073 628 0 28497 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 207776 [startup+102.3 s] /proc/loadavg: 0.98 0.96 0.93 2/54 8339 /proc/meminfo: memFree=325628/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=214500 CPUtime=101.92 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 46460 413 0 0 10181 11 0 0 20 0 1 0 3899749 219648000 31404 18446744073709551615 4194304 6763684 140734296039408 140734296018152 140537934552912 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 53625 31404 1073 628 0 30178 0 Current children cumulated CPU time (s) 101.92 Current children cumulated vsize (KiB) 214500 [startup+162.3 s] /proc/loadavg: 0.99 0.97 0.93 2/54 8339 /proc/meminfo: memFree=325504/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=214500 CPUtime=161.7 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 46460 413 0 0 16159 11 0 0 20 0 1 0 3899749 219648000 31404 18446744073709551615 4194304 6763684 140734296039408 140734296018152 140537934552928 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 53625 31404 1073 628 0 30178 0 Current children cumulated CPU time (s) 161.7 Current children cumulated vsize (KiB) 214500 [startup+222.303 s] /proc/loadavg: 0.99 0.97 0.93 2/54 8339 /proc/meminfo: memFree=325504/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=214500 CPUtime=221.48 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 46472 413 0 0 22137 11 0 0 20 0 1 0 3899749 219648000 31416 18446744073709551615 4194304 6763684 140734296039408 140734296018152 140537916804801 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 53625 31416 1073 628 0 30178 0 Current children cumulated CPU time (s) 221.48 Current children cumulated vsize (KiB) 214500 [startup+282.3 s] /proc/loadavg: 0.99 0.97 0.93 2/54 8339 /proc/meminfo: memFree=325380/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=214500 CPUtime=281.26 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 46472 413 0 0 28115 11 0 0 20 0 1 0 3899749 219648000 31416 18446744073709551615 4194304 6763684 140734296039408 140734296018152 140537916804801 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 53625 31416 1073 628 0 30178 0 Current children cumulated CPU time (s) 281.26 Current children cumulated vsize (KiB) 214500 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.97 0.93 2/54 8339 /proc/meminfo: memFree=325380/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=214500 CPUtime=298.9 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 46472 413 0 0 29879 11 0 0 20 0 1 0 3899749 219648000 31416 18446744073709551615 4194304 6763684 140734296039408 140734296018152 4343746 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 53625 31416 1073 628 0 30178 0 Current children cumulated CPU time (s) 298.9 Current children cumulated vsize (KiB) 214500 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples [startup+300 s] /proc/loadavg: 0.99 0.97 0.93 2/54 8339 /proc/meminfo: memFree=325380/1022884 swapFree=0/0 [pid=8336] ppid=8335 vsize=214500 CPUtime=298.9 /proc/8336/stat : 8336 (smart) R 8335 8336 2806 34818 2806 4202496 46472 413 0 0 29879 11 0 0 20 0 1 0 3899749 219648000 31416 18446744073709551615 4194304 6763684 140734296039408 140734296018152 4343746 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/8336/statm: 53625 31416 1073 628 0 30178 0 Current children cumulated CPU time (s) 298.9 Current children cumulated vsize (KiB) 214500 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.015 CPU time (s): 298.923 CPU user time (s): 298.799 CPU system time (s): 0.124007 CPU usage (%): 99.636 Max. virtual memory (cumulated for all children) (KiB): 214500 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.799 system time used= 0.124007 maximum resident set size= 125664 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 46885 page faults= 0 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 6 involuntary context switches= 4353 runsolver used 0.364022 second user time and 0.732045 second system time The end