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/201108311143/aspcud-1.5/rand21.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand21.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand21.cudf.dudf-random.result -sum(installedsize) 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.18 1.12 0.98 4/39 20457 /proc/meminfo: memFree=830104/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2584 CPUtime=0 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 61030484 2646016 279 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/20456/statm: 646 279 234 194 0 33 0 [pid=20457] ppid=20456 vsize=2584 CPUtime=0 /proc/20457/stat : 20457 (aspcud-1.5) R 20456 20456 19908 34817 19908 4202560 94 0 0 0 0 0 0 0 25 0 1 0 61030484 2646016 118 1283457024 134512640 135304128 4294105424 18446744073709551615 134695055 0 0 0 65538 0 0 0 17 0 0 0 0 /proc/20457/statm: 646 118 72 194 0 33 0 [startup+0.122169 s] /proc/loadavg: 1.18 1.12 0.98 4/39 20457 /proc/meminfo: memFree=830104/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=0.01 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 1520 0 0 0 1 0 0 25 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.206148 s] /proc/loadavg: 1.18 1.12 0.98 4/39 20457 /proc/meminfo: memFree=830104/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=0.01 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 1520 0 0 0 1 0 0 25 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.306162 s] /proc/loadavg: 1.18 1.12 0.98 4/39 20457 /proc/meminfo: memFree=830104/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=0.01 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 1520 0 0 0 1 0 0 25 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.706178 s] /proc/loadavg: 1.18 1.12 0.98 4/39 20457 /proc/meminfo: memFree=830104/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=0.01 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 1520 0 0 0 1 0 0 25 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.50622 s] /proc/loadavg: 1.18 1.12 0.98 2/42 20467 /proc/meminfo: memFree=788296/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=0.01 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 1520 0 0 0 1 0 0 25 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=1928 CPUtime=0 /proc/20465/stat : 20465 (clasp) S 20456 20456 19908 34817 19908 4202496 293 0 0 0 0 0 0 0 25 0 1 0 61030485 1974272 160 1283457024 134512640 136285277 4287681296 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20465/statm: 482 160 144 433 0 47 0 [pid=20466] ppid=20456 vsize=2584 CPUtime=0 /proc/20466/stat : 20466 (gringo) S 20456 20456 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 61030485 2646016 272 1283457024 134512640 136933539 4289574224 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20466/statm: 646 272 242 592 0 51 0 [pid=20467] ppid=20456 vsize=27484 CPUtime=1.34 /proc/20467/stat : 20467 (cudf2lp) R 20456 20456 19908 34817 19908 4202496 7690 0 0 0 132 2 0 0 25 0 1 0 61030485 28143616 6188 1283457024 134512640 135786343 4290471488 18446744073709551615 134614776 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20467/statm: 6871 6188 128 311 0 6558 0 Current children cumulated CPU time (s) 1.35 Current children cumulated vsize (KiB) 34588 [startup+3.10651 s] /proc/loadavg: 1.18 1.12 0.98 2/42 20467 /proc/meminfo: memFree=758132/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.19 /proc/20456/stat : 20456 (aspcud-1.5) R 20455 20456 19908 34817 19908 4202496 580 15027 0 0 0 1 211 7 19 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=6912 CPUtime=0.55 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 1653 0 0 0 55 0 0 0 18 0 1 0 61030485 7077888 1514 1283457024 134512640 136285277 4287681296 18446744073709551615 134615114 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 1728 1514 234 433 0 1293 0 [pid=20466] ppid=20456 vsize=0 CPUtime=0.05 /proc/20466/stat : 20466 (gringo) Z 20456 20456 19908 34817 19908 4202508 1329 0 0 0 5 0 0 0 18 0 1 0 61030485 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/20466/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.79 Current children cumulated vsize (KiB) 9504 [startup+6.30697 s] /proc/loadavg: 1.25 1.13 0.98 2/40 20468 /proc/meminfo: memFree=796728/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=7620 CPUtime=3.74 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 1823 0 0 0 374 0 0 0 25 0 1 0 61030485 7802880 1684 1283457024 134512640 136285277 4287681296 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 1905 1684 234 433 0 1470 0 Current children cumulated CPU time (s) 5.98 Current children cumulated vsize (KiB) 10212 [startup+12.7084 s] /proc/loadavg: 1.23 1.13 0.98 2/40 20468 /proc/meminfo: memFree=795984/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=8296 CPUtime=10.14 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 1987 0 0 0 1014 0 0 0 25 0 1 0 61030485 8495104 1845 1283457024 134512640 136285277 4287681296 18446744073709551615 134966690 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2074 1845 234 433 0 1639 0 Current children cumulated CPU time (s) 12.38 Current children cumulated vsize (KiB) 10888 [startup+25.5113 s] /proc/loadavg: 1.18 1.12 0.98 2/40 20470 /proc/meminfo: memFree=795240/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=8904 CPUtime=22.94 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 2152 0 0 0 2294 0 0 0 25 0 1 0 61030485 9117696 2010 1283457024 134512640 136285277 4287681296 18446744073709551615 134955168 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2226 2010 234 433 0 1791 0 Current children cumulated CPU time (s) 25.18 Current children cumulated vsize (KiB) 11496 [startup+51.1116 s] /proc/loadavg: 1.12 1.11 0.98 2/40 20472 /proc/meminfo: memFree=794372/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=9832 CPUtime=48.5 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 2557 0 0 0 4850 0 0 0 25 0 1 0 61030485 10067968 2234 1283457024 134512640 136285277 4287681296 18446744073709551615 134966793 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2458 2234 234 433 0 2023 0 Current children cumulated CPU time (s) 50.74 Current children cumulated vsize (KiB) 12424 [startup+102.313 s] /proc/loadavg: 1.05 1.09 0.98 2/39 20475 /proc/meminfo: memFree=793652/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=10632 CPUtime=99.65 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 2801 0 0 0 9965 0 0 0 25 0 1 0 61030485 10887168 2438 1283457024 134512640 136285277 4287681296 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2658 2438 234 433 0 2223 0 Current children cumulated CPU time (s) 101.89 Current children cumulated vsize (KiB) 13224 [startup+162.31 s] /proc/loadavg: 1.02 1.07 0.98 2/38 20475 /proc/meminfo: memFree=792916/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=11320 CPUtime=159.6 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 3344 0 0 0 15960 0 0 0 25 0 1 0 61030485 11591680 2604 1283457024 134512640 136285277 4287681296 18446744073709551615 134615133 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2830 2604 234 433 0 2395 0 Current children cumulated CPU time (s) 161.84 Current children cumulated vsize (KiB) 13912 [startup+222.313 s] /proc/loadavg: 1.00 1.06 0.98 2/38 20475 /proc/meminfo: memFree=792668/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=11376 CPUtime=219.54 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 3419 0 0 0 21952 2 0 0 25 0 1 0 61030485 11649024 2637 1283457024 134512640 136285277 4287681296 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2844 2637 234 433 0 2409 0 Current children cumulated CPU time (s) 221.78 Current children cumulated vsize (KiB) 13968 [startup+282.304 s] /proc/loadavg: 1.00 1.04 0.98 2/38 20475 /proc/meminfo: memFree=792420/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=11676 CPUtime=279.5 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 3658 0 0 0 27947 3 0 0 25 0 1 0 61030485 11956224 2711 1283457024 134512640 136285277 4287681296 18446744073709551615 134959788 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2919 2711 234 433 0 2484 0 Current children cumulated CPU time (s) 281.74 Current children cumulated vsize (KiB) 14268 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.606 s] /proc/loadavg: 1.00 1.04 0.98 2/38 20475 /proc/meminfo: memFree=792420/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=11724 CPUtime=287.8 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 3664 0 0 0 28777 3 0 0 25 0 1 0 61030485 12005376 2717 1283457024 134512640 136285277 4287681296 18446744073709551615 134669425 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2931 2717 234 433 0 2496 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 14316 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.606 s] /proc/loadavg: 1.00 1.04 0.98 2/38 20475 /proc/meminfo: memFree=792420/1048576 swapFree=0/0 [pid=20456] ppid=20455 vsize=2592 CPUtime=2.24 /proc/20456/stat : 20456 (aspcud-1.5) S 20455 20456 19908 34817 19908 4202496 580 16356 0 0 0 1 216 7 17 0 1 0 61030484 2654208 298 1283457024 134512640 135304128 4294105424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20456/statm: 648 298 251 194 0 35 0 [pid=20465] ppid=20456 vsize=11724 CPUtime=287.8 /proc/20465/stat : 20465 (clasp) R 20456 20456 19908 34817 19908 4202496 3664 0 0 0 28777 3 0 0 25 0 1 0 61030485 12005376 2717 1283457024 134512640 136285277 4287681296 18446744073709551615 134669425 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20465/statm: 2931 2717 234 433 0 2496 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 14316 Child status: 0 Real time (s): 290.627 CPU time (s): 290.082 CPU user time (s): 289.942 CPU system time (s): 0.140008 CPU usage (%): 99.8125 Max. virtual memory (cumulated for all children) (KiB): 53268 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.942 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= 24179 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= 217 involuntary context switches= 3743 runsolver used 0 second user time and 0 second system time The end