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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012091704/aspcud-1.3/rand847939.cudf.difficult.log.runsolver ./aspcud-1.3 /home/misc2010/data/2010/difficult//rand847939.cudf /home/misc2010/tmp/201012091704/aspcud-1.3/rand847939.cudf.difficult.result -changed,-notuptodate,-removed,-new Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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 Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.01 0.98 0.98 5/39 7120 /proc/meminfo: memFree=446372/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2584 CPUtime=0 /proc/7119/stat : 7119 (aspcud-1.3) R 7118 7119 25521 34816 2180 4202496 368 0 0 0 0 0 0 0 25 0 1 0 901601887 2646016 281 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/7119/statm: 646 281 237 194 0 32 0 [pid=7120] ppid=7119 vsize=2584 CPUtime=0 /proc/7120/stat : 7120 (aspcud-1.3) R 7119 7119 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 901601887 2646016 44 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/7120/statm: 646 44 0 194 0 32 0 [startup+0.140838 s] /proc/loadavg: 1.01 0.98 0.98 5/39 7120 /proc/meminfo: memFree=446372/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=0.01 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 1506 0 0 0 0 0 1 25 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.210855 s] /proc/loadavg: 1.01 0.98 0.98 5/39 7120 /proc/meminfo: memFree=446372/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=0.01 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 1506 0 0 0 0 0 1 25 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.310879 s] /proc/loadavg: 1.01 0.98 0.98 5/39 7120 /proc/meminfo: memFree=446372/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=0.01 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 1506 0 0 0 0 0 1 25 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.710972 s] /proc/loadavg: 1.01 0.98 0.98 5/39 7120 /proc/meminfo: memFree=446372/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=0.01 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 1506 0 0 0 0 0 1 25 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.51118 s] /proc/loadavg: 1.01 0.98 0.98 3/41 7130 /proc/meminfo: memFree=433820/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=12588 CPUtime=0.3 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 3258 0 0 0 28 2 0 0 18 0 1 0 901601888 12890112 2773 1283457024 134512640 136223643 4291384976 18446744073709551615 134870674 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 3147 2773 225 418 0 2727 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 15180 [startup+3.1115 s] /proc/loadavg: 1.01 0.98 0.98 2/40 7130 /proc/meminfo: memFree=432968/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=17900 CPUtime=1.89 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 4572 0 0 0 187 2 0 0 21 0 1 0 901601888 18329600 4087 1283457024 134512640 136223643 4291384976 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 4475 4087 225 418 0 4055 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 20492 [startup+6.31228 s] /proc/loadavg: 1.01 0.98 0.98 2/40 7130 /proc/meminfo: memFree=430736/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=17900 CPUtime=5.09 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 4572 0 0 0 507 2 0 0 25 0 1 0 901601888 18329600 4087 1283457024 134512640 136223643 4291384976 18446744073709551615 134611056 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 4475 4087 225 418 0 4055 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 20492 [startup+12.7136 s] /proc/loadavg: 1.01 0.98 0.98 2/40 7130 /proc/meminfo: memFree=426768/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=23576 CPUtime=11.49 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 5986 0 0 0 1147 2 0 0 25 0 1 0 901601888 24141824 5501 1283457024 134512640 136223643 4291384976 18446744073709551615 134711227 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 5894 5501 225 418 0 5474 0 Current children cumulated CPU time (s) 12.69 Current children cumulated vsize (KiB) 26168 [startup+25.5063 s] /proc/loadavg: 1.01 0.98 0.98 2/40 7130 /proc/meminfo: memFree=416228/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=32436 CPUtime=24.26 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 8193 0 0 0 2423 3 0 0 25 0 1 0 901601888 33214464 7708 1283457024 134512640 136223643 4291384976 18446744073709551615 134930964 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 8109 7708 225 418 0 7689 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 35028 [startup+51.1119 s] /proc/loadavg: 1.00 0.98 0.98 2/40 7130 /proc/meminfo: memFree=410276/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=37676 CPUtime=49.84 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 9700 0 0 0 4981 3 0 0 25 0 1 0 901601888 38580224 9047 1283457024 134512640 136223643 4291384976 18446744073709551615 134928984 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 9419 9047 225 418 0 8999 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 40268 [startup+102.312 s] /proc/loadavg: 1.00 0.98 0.98 2/40 7130 /proc/meminfo: memFree=405936/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=42536 CPUtime=101 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 10880 0 0 0 10097 3 0 0 25 0 1 0 901601888 43556864 10227 1283457024 134512640 136223643 4291384976 18446744073709551615 134931115 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 10634 10227 225 418 0 10214 0 Current children cumulated CPU time (s) 102.2 Current children cumulated vsize (KiB) 45128 [startup+162.306 s] /proc/loadavg: 1.00 0.98 0.98 2/40 7130 /proc/meminfo: memFree=400356/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=47980 CPUtime=160.94 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 12254 0 0 0 16091 3 0 0 25 0 1 0 901601888 49131520 11601 1283457024 134512640 136223643 4291384976 18446744073709551615 134611158 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 11995 11601 225 418 0 11575 0 Current children cumulated CPU time (s) 162.14 Current children cumulated vsize (KiB) 50572 [startup+222.311 s] /proc/loadavg: 1.00 0.98 0.98 2/40 7130 /proc/meminfo: memFree=400108/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=48060 CPUtime=220.88 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 12839 0 0 0 22085 3 0 0 25 0 1 0 901601888 49213440 11613 1283457024 134512640 136223643 4291384976 18446744073709551615 134924290 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 12015 11613 225 418 0 11595 0 Current children cumulated CPU time (s) 222.08 Current children cumulated vsize (KiB) 50652 [startup+282.316 s] /proc/loadavg: 1.00 0.98 0.98 2/40 7130 /proc/meminfo: memFree=399116/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=48548 CPUtime=280.82 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 13262 0 0 0 28078 4 0 0 25 0 1 0 901601888 49713152 11751 1283457024 134512640 136223643 4291384976 18446744073709551615 134934550 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 12137 11751 225 418 0 11717 0 Current children cumulated CPU time (s) 282.02 Current children cumulated vsize (KiB) 51140 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.307 s] /proc/loadavg: 1.00 0.98 0.98 2/40 7130 /proc/meminfo: memFree=399116/1048576 swapFree=2095372/2097144 [pid=7119] ppid=7118 vsize=2592 CPUtime=1.2 /proc/7119/stat : 7119 (aspcud-1.3) S 7118 7119 25521 34816 2180 4202496 572 14351 0 0 0 0 112 8 17 0 1 0 901601887 2654208 299 1283457024 134512640 135304128 4286827088 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7119/statm: 648 299 253 194 0 34 0 [pid=7128] ppid=7119 vsize=48548 CPUtime=288.81 /proc/7128/stat : 7128 (clasp) R 7119 7119 25521 34816 2180 4202496 13262 0 0 0 28877 4 0 0 25 0 1 0 901601888 49713152 11751 1283457024 134512640 136223643 4291384976 18446744073709551615 134924387 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/7128/statm: 12137 11751 225 418 0 11717 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 51140 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.329 CPU time (s): 290.05 CPU user time (s): 289.91 CPU system time (s): 0.140008 CPU usage (%): 99.904 Max. virtual memory (cumulated for all children) (KiB): 52420 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.91 system time used= 0.140008 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 30797 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= 361 involuntary context switches= 3845 runsolver used 0 second user time and 0 second system time The end