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/27.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install xpdf-common planner regina3-dev isdnutils-doc mailagent 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.99 2/53 10806 /proc/meminfo: memFree=397344/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=3152 CPUtime=0 /proc/10806/stat : 10806 (runsolver) R 10805 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 5367962 3227648 32 18446744073709551615 134512640 134586868 4288220064 4288218112 4152169520 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.146448 s] /proc/loadavg: 0.92 0.98 0.99 2/53 10806 /proc/meminfo: memFree=397344/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=120148 CPUtime=0.13 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 10109 0 0 0 12 1 0 0 20 0 1 0 5367962 123031552 8829 18446744073709551615 4194304 6763684 140734629078928 140734629073928 5511944 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 30037 8829 1043 628 0 7620 0 Current children cumulated CPU time (s) 0.13 Current children cumulated vsize (KiB) 120148 [startup+0.20027 s] /proc/loadavg: 0.92 0.98 0.99 2/53 10806 /proc/meminfo: memFree=397344/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=121916 CPUtime=0.19 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 11872 411 0 0 16 3 0 0 20 0 1 0 5367962 124841984 8182 18446744073709551615 4194304 6763684 140734629078928 140734629074904 5727865 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 30479 8182 1058 628 0 7032 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 121916 [startup+0.300249 s] /proc/loadavg: 0.92 0.98 0.99 2/53 10806 /proc/meminfo: memFree=397344/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=139308 CPUtime=0.28 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 18834 411 0 0 24 4 0 0 20 0 1 0 5367962 142651392 12585 18446744073709551615 4194304 6763684 140734629078928 140734629074904 5517868 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 34827 12585 1059 628 0 11380 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 139308 [startup+0.700179 s] /proc/loadavg: 0.92 0.98 0.99 2/53 10806 /proc/meminfo: memFree=397344/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=199928 CPUtime=0.68 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 37520 411 0 0 60 8 0 0 20 0 1 0 5367962 204726272 27695 18446744073709551615 4194304 6763684 140734629078928 140734629074920 139934109902496 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 49982 27695 1059 628 0 26535 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 199928 [startup+1.5002 s] /proc/loadavg: 0.92 0.98 0.99 2/54 10809 /proc/meminfo: memFree=253868/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=236420 CPUtime=1.48 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 52868 411 0 0 133 15 0 0 20 0 1 0 5367962 242094080 36864 18446744073709551615 4194304 6763684 140734629078928 140734629075456 5763084 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 59105 36864 1068 628 0 35658 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 236420 [startup+3.10022 s] /proc/loadavg: 0.92 0.98 0.99 2/54 10809 /proc/meminfo: memFree=214064/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=276008 CPUtime=3.07 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 62777 411 0 0 291 16 0 0 20 0 1 0 5367962 282632192 46763 18446744073709551615 4194304 6763684 140734629078928 140734629075880 139934091656896 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69002 46763 1070 628 0 45555 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 276008 [startup+6.30019 s] /proc/loadavg: 0.93 0.98 0.99 2/54 10809 /proc/meminfo: memFree=213940/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=276008 CPUtime=6.26 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 62781 411 0 0 610 16 0 0 20 0 1 0 5367962 282632192 46766 18446744073709551615 4194304 6763684 140734629078928 140734629075880 139934091656922 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69002 46766 1073 628 0 45555 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 276008 [startup+12.7002 s] /proc/loadavg: 0.93 0.98 0.99 2/54 10809 /proc/meminfo: memFree=213816/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=276008 CPUtime=12.63 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 62781 411 0 0 1247 16 0 0 20 0 1 0 5367962 282632192 46766 18446744073709551615 4194304 6763684 140734629078928 140734629075880 139934091657056 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69002 46766 1073 628 0 45555 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 276008 [startup+25.5002 s] /proc/loadavg: 0.95 0.98 0.99 2/54 10809 /proc/meminfo: memFree=213072/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=276624 CPUtime=25.38 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 62936 411 0 0 2522 16 0 0 20 0 1 0 5367962 283262976 46920 18446744073709551615 4194304 6763684 140734629078928 140734629032664 139934091660600 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69156 46920 1073 628 0 45709 0 Current children cumulated CPU time (s) 25.38 Current children cumulated vsize (KiB) 276624 [startup+51.1002 s] /proc/loadavg: 0.96 0.98 0.99 2/54 10809 /proc/meminfo: memFree=212576/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=277212 CPUtime=50.89 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 63084 411 0 0 5073 16 0 0 20 0 1 0 5367962 283865088 47067 18446744073709551615 4194304 6763684 140734629078928 140734629031608 139934091656922 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69303 47067 1073 628 0 45856 0 Current children cumulated CPU time (s) 50.89 Current children cumulated vsize (KiB) 277212 [startup+102.3 s] /proc/loadavg: 0.98 0.98 0.99 2/54 10809 /proc/meminfo: memFree=212080/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=277536 CPUtime=101.9 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 63165 411 0 0 10174 16 0 0 20 0 1 0 5367962 284196864 47148 18446744073709551615 4194304 6763684 140734629078928 140734629031608 139934091657056 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69384 47148 1073 628 0 45937 0 Current children cumulated CPU time (s) 101.9 Current children cumulated vsize (KiB) 277536 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 10809 /proc/meminfo: memFree=212080/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=277536 CPUtime=161.67 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 63165 411 0 0 16151 16 0 0 20 0 1 0 5367962 284196864 47148 18446744073709551615 4194304 6763684 140734629078928 140734629031608 139934091657065 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69384 47148 1073 628 0 45937 0 Current children cumulated CPU time (s) 161.67 Current children cumulated vsize (KiB) 277536 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.99 2/54 10809 /proc/meminfo: memFree=211832/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=277680 CPUtime=221.44 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 63225 411 0 0 22128 16 0 0 20 0 1 0 5367962 284344320 47208 18446744073709551615 4194304 6763684 140734629078928 140734629031608 139934091656922 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69420 47208 1073 628 0 45973 0 Current children cumulated CPU time (s) 221.44 Current children cumulated vsize (KiB) 277680 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.99 2/54 10809 /proc/meminfo: memFree=211832/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=277872 CPUtime=281.22 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 63261 411 0 0 28106 16 0 0 20 0 1 0 5367962 284540928 47244 18446744073709551615 4194304 6763684 140734629078928 140734629031608 139934073908929 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69468 47244 1073 628 0 46021 0 Current children cumulated CPU time (s) 281.22 Current children cumulated vsize (KiB) 277872 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 0.99 0.98 0.99 2/54 10809 /proc/meminfo: memFree=211708/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=277872 CPUtime=298.85 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 63261 411 0 0 29869 16 0 0 20 0 1 0 5367962 284540928 47244 18446744073709551615 4194304 6763684 140734629078928 140734629031608 139934091656922 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69468 47244 1073 628 0 46021 0 Current children cumulated CPU time (s) 298.85 Current children cumulated vsize (KiB) 277872 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.99 2/54 10809 /proc/meminfo: memFree=211708/1022884 swapFree=0/0 [pid=10806] ppid=10805 vsize=277872 CPUtime=298.85 /proc/10806/stat : 10806 (smart) R 10805 10806 2806 34818 2806 4202496 63261 411 0 0 29869 16 0 0 20 0 1 0 5367962 284540928 47244 18446744073709551615 4194304 6763684 140734629078928 140734629031608 139934091656922 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/10806/statm: 69468 47244 1073 628 0 46021 0 Current children cumulated CPU time (s) 298.85 Current children cumulated vsize (KiB) 277872 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.02 CPU time (s): 298.887 CPU user time (s): 298.699 CPU system time (s): 0.188011 CPU usage (%): 99.6223 Max. virtual memory (cumulated for all children) (KiB): 277872 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.699 system time used= 0.188011 maximum resident set size= 188976 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 63672 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= 4350 runsolver used 0.400025 second user time and 0.732045 second system time The end