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/logs/64.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install lg-issue103 rbldnsd libexpat-ocaml kernel-headers-2.6.8-13-em64t-p4 mergelog 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.92 0.98 0.98 2/53 12488 /proc/meminfo: memFree=393668/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=3152 CPUtime=0 /proc/12488/stat : 12488 (runsolver) R 12487 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 6425704 3227648 32 18446744073709551615 134512640 134586868 4288961728 4288959776 4151252016 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.179912 s] /proc/loadavg: 0.92 0.98 0.98 2/53 12488 /proc/meminfo: memFree=393668/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=117060 CPUtime=0.17 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 10983 414 0 0 12 5 0 0 20 0 1 0 6425704 119869440 7523 18446744073709551615 4194304 6763684 140736592487968 140736592447336 140263002704272 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 29265 7523 1055 628 0 6333 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 117060 [startup+0.200227 s] /proc/loadavg: 0.92 0.98 0.98 2/53 12488 /proc/meminfo: memFree=393668/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=122624 CPUtime=0.19 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 12144 414 0 0 14 5 0 0 20 0 1 0 6425704 125566976 8391 18446744073709551615 4194304 6763684 140736592487968 140736592483944 5727849 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 30656 8391 1058 628 0 7209 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 122624 [startup+0.300228 s] /proc/loadavg: 0.92 0.98 0.98 2/53 12488 /proc/meminfo: memFree=393668/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=139312 CPUtime=0.29 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 18834 414 0 0 22 7 0 0 20 0 1 0 6425704 142655488 12585 18446744073709551615 4194304 6763684 140736592487968 140736592483944 5520656 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 34828 12585 1059 628 0 11381 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 139312 [startup+0.700185 s] /proc/loadavg: 0.92 0.98 0.98 2/53 12488 /proc/meminfo: memFree=393668/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=200864 CPUtime=0.69 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 37772 414 0 0 59 10 0 0 20 0 1 0 6425704 205684736 27946 18446744073709551615 4194304 6763684 140736592487968 140736592483960 4302176 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 50216 27946 1059 628 0 26769 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 200864 [startup+1.5002 s] /proc/loadavg: 0.92 0.98 0.98 2/54 12491 /proc/meminfo: memFree=249324/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=236420 CPUtime=1.48 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 52867 414 0 0 134 14 0 0 20 0 1 0 6425704 242094080 36863 18446744073709551615 4194304 6763684 140736592487968 140736592484496 5517875 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 59105 36863 1068 628 0 35658 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 236420 [startup+3.10021 s] /proc/loadavg: 0.92 0.98 0.98 2/54 12491 /proc/meminfo: memFree=210388/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=276012 CPUtime=3.08 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 62778 414 0 0 291 17 0 0 20 0 1 0 6425704 282636288 46763 18446744073709551615 4194304 6763684 140736592487968 140736592484920 140263002981896 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69003 46763 1070 628 0 45556 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 276012 [startup+6.3002 s] /proc/loadavg: 0.93 0.98 0.98 2/54 12491 /proc/meminfo: memFree=210264/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=276012 CPUtime=6.27 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 62783 414 0 0 610 17 0 0 20 0 1 0 6425704 282636288 46766 18446744073709551615 4194304 6763684 140736592487968 140736592484920 140262985232065 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69003 46766 1073 628 0 45556 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 276012 [startup+12.7002 s] /proc/loadavg: 0.93 0.98 0.98 2/54 12491 /proc/meminfo: memFree=210140/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=276012 CPUtime=12.64 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 62784 414 0 0 1247 17 0 0 20 0 1 0 6425704 282636288 46766 18446744073709551615 4194304 6763684 140736592487968 140736592484920 5221439 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69003 46766 1073 628 0 45556 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 276012 [startup+25.5002 s] /proc/loadavg: 0.95 0.98 0.98 2/54 12491 /proc/meminfo: memFree=210140/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=276012 CPUtime=25.39 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 62784 414 0 0 2522 17 0 0 20 0 1 0 6425704 282636288 46766 18446744073709551615 4194304 6763684 140736592487968 140736592484920 140263002983732 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69003 46766 1073 628 0 45556 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 276012 [startup+51.1002 s] /proc/loadavg: 0.96 0.98 0.98 2/54 12491 /proc/meminfo: memFree=210140/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=276012 CPUtime=50.9 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 62784 414 0 0 5073 17 0 0 20 0 1 0 6425704 282636288 46766 18446744073709551615 4194304 6763684 140736592487968 140736592484920 140262985232065 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69003 46766 1073 628 0 45556 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 276012 [startup+102.3 s] /proc/loadavg: 0.98 0.98 0.98 2/54 12491 /proc/meminfo: memFree=208652/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=277356 CPUtime=101.91 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 63121 414 0 0 10174 17 0 0 20 0 1 0 6425704 284012544 47102 18446744073709551615 4194304 6763684 140736592487968 140736592431672 140263002980192 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69339 47102 1073 628 0 45892 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 277356 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.98 2/54 12491 /proc/meminfo: memFree=208528/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=277500 CPUtime=161.69 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 63157 414 0 0 16152 17 0 0 20 0 1 0 6425704 284160000 47138 18446744073709551615 4194304 6763684 140736592487968 140736592431672 140262985232074 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69375 47138 1073 628 0 45928 0 Current children cumulated CPU time (s) 161.69 Current children cumulated vsize (KiB) 277500 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.98 2/54 12491 /proc/meminfo: memFree=208280/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=277644 CPUtime=221.47 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 63193 414 0 0 22130 17 0 0 20 0 1 0 6425704 284307456 47174 18446744073709551615 4194304 6763684 140736592487968 140736592431672 140263002981896 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69411 47174 1073 628 0 45964 0 Current children cumulated CPU time (s) 221.47 Current children cumulated vsize (KiB) 277644 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.98 2/54 12491 /proc/meminfo: memFree=208280/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=277644 CPUtime=281.24 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 63216 414 0 0 28107 17 0 0 20 0 1 0 6425704 284307456 47197 18446744073709551615 4194304 6763684 140736592487968 140736592431672 140263002980058 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69411 47197 1073 628 0 45964 0 Current children cumulated CPU time (s) 281.24 Current children cumulated vsize (KiB) 277644 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.98 2/54 12491 /proc/meminfo: memFree=208280/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=277644 CPUtime=298.88 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 63216 414 0 0 29871 17 0 0 20 0 1 0 6425704 284307456 47197 18446744073709551615 4194304 6763684 140736592487968 140736592431672 140263002980245 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69411 47197 1073 628 0 45964 0 Current children cumulated CPU time (s) 298.88 Current children cumulated vsize (KiB) 277644 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.98 0.98 2/54 12491 /proc/meminfo: memFree=208280/1022884 swapFree=0/0 [pid=12488] ppid=12487 vsize=277644 CPUtime=298.88 /proc/12488/stat : 12488 (smart) R 12487 12488 2806 34818 2806 4202496 63216 414 0 0 29871 17 0 0 20 0 1 0 6425704 284307456 47197 18446744073709551615 4194304 6763684 140736592487968 140736592431672 140263002980245 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/12488/statm: 69411 47197 1073 628 0 45964 0 Current children cumulated CPU time (s) 298.88 Current children cumulated vsize (KiB) 277644 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.017 CPU time (s): 298.903 CPU user time (s): 298.719 CPU system time (s): 0.184011 CPU usage (%): 99.6285 Max. virtual memory (cumulated for all children) (KiB): 277644 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.719 system time used= 0.184011 maximum resident set size= 188788 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 63630 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= 4359 runsolver used 0.428026 second user time and 0.688043 second system time The end