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/21.runsolver.smart smart --config-file=/home/cbse/var/lib/smart/config install liquidwar-data python2.3-weblib kaffe-pthreads plplot-bin python-gtk2-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.92 0.98 0.98 2/53 25764 /proc/meminfo: memFree=393652/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=3152 CPUtime=0 /proc/25764/stat : 25764 (runsolver) R 25763 2806 2806 34818 2806 4202560 0 0 0 0 0 0 0 0 20 0 1 0 14861455 3227648 33 18446744073709551615 134512640 134586868 4292588256 4292586304 4151194672 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.153287 s] /proc/loadavg: 0.92 0.98 0.98 2/53 25764 /proc/meminfo: memFree=393652/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=120072 CPUtime=0.14 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 10092 0 0 0 12 2 0 0 20 0 1 0 14861455 122953728 8811 18446744073709551615 4194304 6763684 140737286399728 140737286394728 5517868 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 30018 8811 1043 628 0 7601 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 120072 [startup+0.200267 s] /proc/loadavg: 0.92 0.98 0.98 2/53 25764 /proc/meminfo: memFree=393652/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=132852 CPUtime=0.19 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 14800 0 0 0 16 3 0 0 20 0 1 0 14861455 136040448 11982 18446744073709551615 4194304 6763684 140737286399728 140737286394808 4411810 0 0 16781312 2 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 33213 11982 1043 628 0 10796 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 132852 [startup+0.30026 s] /proc/loadavg: 0.92 0.98 0.98 2/53 25764 /proc/meminfo: memFree=393652/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=136212 CPUtime=0.28 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 21505 412 0 0 23 5 0 0 20 0 1 0 14861455 139481088 11830 18446744073709551615 4194304 6763684 140737286399728 140737286395704 5511944 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 34053 11830 1058 628 0 10606 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 136212 [startup+0.700193 s] /proc/loadavg: 0.92 0.98 0.98 2/53 25764 /proc/meminfo: memFree=393652/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=186196 CPUtime=0.69 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 35534 412 0 0 60 9 0 0 20 0 1 0 14861455 190664704 24260 18446744073709551615 4194304 6763684 140737286399728 140737286395784 5763084 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 46549 24260 1059 628 0 23102 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 186196 [startup+1.50019 s] /proc/loadavg: 0.92 0.98 0.98 2/54 25767 /proc/meminfo: memFree=251912/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=289632 CPUtime=1.48 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 67586 412 0 0 134 14 0 0 20 0 1 0 14861455 296583168 50161 18446744073709551615 4194304 6763684 140737286399728 140737286395784 5520656 0 0 16777216 134217730 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 72408 50161 1059 628 0 48961 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 289632 [startup+3.1002 s] /proc/loadavg: 0.92 0.98 0.98 2/54 25767 /proc/meminfo: memFree=128780/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=347856 CPUtime=3.08 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 94428 412 0 0 286 22 0 0 20 0 1 0 14861455 356204544 64682 18446744073709551615 4194304 6763684 140737286399728 140737286395768 4705990 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 86964 64682 1068 628 0 63517 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 347856 [startup+6.30019 s] /proc/loadavg: 0.93 0.98 0.98 2/54 25767 /proc/meminfo: memFree=120720/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=365572 CPUtime=6.27 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 98901 412 0 0 603 24 0 0 20 0 1 0 14861455 374345728 69144 18446744073709551615 4194304 6763684 140737286399728 140737286396680 139839993855681 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 91393 69144 1070 628 0 67946 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 365572 [startup+12.7002 s] /proc/loadavg: 0.93 0.98 0.98 2/54 25767 /proc/meminfo: memFree=120596/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=365572 CPUtime=12.64 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 98904 412 0 0 1240 24 0 0 20 0 1 0 14861455 374345728 69147 18446744073709551615 4194304 6763684 140737286399728 140737286396680 139840011603674 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 91393 69147 1073 628 0 67946 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 365572 [startup+25.5002 s] /proc/loadavg: 0.95 0.98 0.98 2/54 25767 /proc/meminfo: memFree=120596/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=365572 CPUtime=25.39 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 98904 412 0 0 2515 24 0 0 20 0 1 0 14861455 374345728 69147 18446744073709551615 4194304 6763684 140737286399728 140737286396680 139840011603678 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 91393 69147 1073 628 0 67946 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 365572 [startup+51.1002 s] /proc/loadavg: 0.96 0.98 0.98 2/54 25767 /proc/meminfo: memFree=120596/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=365572 CPUtime=50.9 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 98904 412 0 0 5066 24 0 0 20 0 1 0 14861455 374345728 69147 18446744073709551615 4194304 6763684 140737286399728 140737286396680 139839993855681 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 91393 69147 1073 628 0 67946 0 Current children cumulated CPU time (s) 50.9 Current children cumulated vsize (KiB) 365572 [startup+102.3 s] /proc/loadavg: 0.98 0.98 0.98 2/54 25767 /proc/meminfo: memFree=120472/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=365572 CPUtime=101.91 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 98909 412 0 0 10167 24 0 0 20 0 1 0 14861455 374345728 69147 18446744073709551615 4194304 6763684 140737286399728 140737286396680 139840011603674 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 91393 69147 1073 628 0 67946 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 365572 [startup+162.3 s] /proc/loadavg: 0.99 0.98 0.98 2/54 25767 /proc/meminfo: memFree=117248/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=368788 CPUtime=161.68 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 99718 412 0 0 16144 24 0 0 20 0 1 0 14861455 377638912 69951 18446744073709551615 4194304 6763684 140737286399728 140737286311752 4510825 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 92197 69951 1073 628 0 68750 0 Current children cumulated CPU time (s) 161.68 Current children cumulated vsize (KiB) 368788 [startup+222.303 s] /proc/loadavg: 0.99 0.98 0.98 2/54 25767 /proc/meminfo: memFree=116628/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=369364 CPUtime=221.45 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 99886 412 0 0 22121 24 0 0 20 0 1 0 14861455 378228736 70119 18446744073709551615 4194304 6763684 140737286399728 140737286309304 139840011605512 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 92341 70119 1073 628 0 68894 0 Current children cumulated CPU time (s) 221.45 Current children cumulated vsize (KiB) 369364 [startup+282.3 s] /proc/loadavg: 0.99 0.98 0.98 2/54 25767 /proc/meminfo: memFree=116628/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=369556 CPUtime=281.22 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 99935 412 0 0 28098 24 0 0 20 0 1 0 14861455 378425344 70167 18446744073709551615 4194304 6763684 140737286399728 140737286311752 4414165 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 92389 70167 1073 628 0 68942 0 Current children cumulated CPU time (s) 281.22 Current children cumulated vsize (KiB) 369556 Maximum wall clock time exceeded: sending signal-name then SIGKILL [startup+300 s] /proc/loadavg: 1.07 1.00 0.99 2/54 25767 /proc/meminfo: memFree=116380/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=369748 CPUtime=298.86 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 99983 412 0 0 29862 24 0 0 20 0 1 0 14861455 378621952 70215 18446744073709551615 4194304 6763684 140737286399728 140737286308248 5221439 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 92437 70215 1073 628 0 68990 0 Current children cumulated CPU time (s) 298.86 Current children cumulated vsize (KiB) 369748 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: 1.07 1.00 0.99 2/54 25767 /proc/meminfo: memFree=116380/1022884 swapFree=0/0 [pid=25764] ppid=25763 vsize=369748 CPUtime=298.86 /proc/25764/stat : 25764 (smart) R 25763 25764 2806 34818 2806 4202496 99983 412 0 0 29862 24 0 0 20 0 1 0 14861455 378621952 70215 18446744073709551615 4194304 6763684 140737286399728 140737286308248 5221439 0 0 16777216 134217734 0 0 0 17 0 0 0 0 0 0 /proc/25764/statm: 92437 70215 1073 628 0 68990 0 Current children cumulated CPU time (s) 298.86 Current children cumulated vsize (KiB) 369748 Child ended because it received signal 15 (SIGTERM) Real time (s): 300.029 CPU time (s): 298.895 CPU user time (s): 298.627 CPU system time (s): 0.268016 CPU usage (%): 99.622 Max. virtual memory (cumulated for all children) (KiB): 369748 getrusage(RUSAGE_CHILDREN,...) data: user time used= 298.627 system time used= 0.268016 maximum resident set size= 280860 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 100395 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= 4336 runsolver used 0.340021 second user time and 0.792049 second system time The end