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/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/bccf69ae-db9e-11df-9a24-00163e3d3b7c.cudf.dudf-real.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: 0.92 0.98 0.99 4/36 501 /proc/meminfo: memFree=696676/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2588 CPUtime=0 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 25 0 1 0 67341229 2650112 279 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/499/statm: 647 279 234 194 0 34 0 [pid=500] ppid=499 vsize=2588 CPUtime=0 /proc/500/stat : 500 (aspcud-1.5) R 499 499 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 67341229 2650112 132 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/500/statm: 647 132 86 194 0 34 0 [pid=501] ppid=500 vsize=2588 CPUtime=0 /proc/501/stat : 501 (aspcud-1.5) R 500 499 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67341229 2650112 46 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/501/statm: 647 46 0 194 0 34 0 [startup+0.170021 s] /proc/loadavg: 0.92 0.98 0.99 4/36 501 /proc/meminfo: memFree=696676/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=0.01 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.211366 s] /proc/loadavg: 0.92 0.98 0.99 4/36 501 /proc/meminfo: memFree=696676/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=0.01 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.311419 s] /proc/loadavg: 0.92 0.98 0.99 4/36 501 /proc/meminfo: memFree=696676/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=0.01 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.706043 s] /proc/loadavg: 0.92 0.98 0.99 4/36 501 /proc/meminfo: memFree=696676/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=0.01 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 1521 0 0 0 0 0 1 25 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.51218 s] /proc/loadavg: 0.92 0.98 0.99 2/38 510 /proc/meminfo: memFree=653704/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.12 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 10464 0 0 0 0 108 4 18 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=6236 CPUtime=0.03 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 1464 0 0 0 3 0 0 0 18 0 1 0 67341230 6385664 1250 1283457024 134512640 136285277 4293544096 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 1559 1250 177 433 0 1124 0 [pid=509] ppid=499 vsize=10308 CPUtime=0.24 /proc/509/stat : 509 (gringo) R 499 499 19908 34817 19908 4202496 2603 0 0 0 24 0 0 0 18 0 1 0 67341230 10555392 1841 1283457024 134512640 136933539 4292970640 18446744073709551615 136204839 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/509/statm: 2577 1841 253 592 0 1982 0 Current children cumulated CPU time (s) 1.39 Current children cumulated vsize (KiB) 19140 [startup+3.11239 s] /proc/loadavg: 0.92 0.98 0.99 2/36 510 /proc/meminfo: memFree=668988/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=15592 CPUtime=1.37 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 4488 0 0 0 136 1 0 0 19 0 1 0 67341230 15966208 3686 1283457024 134512640 136285277 4293544096 18446744073709551615 134650365 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 3898 3686 234 433 0 3463 0 Current children cumulated CPU time (s) 2.98 Current children cumulated vsize (KiB) 18188 [startup+6.31297 s] /proc/loadavg: 0.93 0.98 0.99 2/36 510 /proc/meminfo: memFree=653984/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=32352 CPUtime=4.58 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 9039 0 0 0 456 2 0 0 25 0 1 0 67341230 33128448 7876 1283457024 134512640 136285277 4293544096 18446744073709551615 134963352 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 8088 7876 234 433 0 7653 0 Current children cumulated CPU time (s) 6.19 Current children cumulated vsize (KiB) 34948 [startup+12.7043 s] /proc/loadavg: 0.93 0.98 0.99 2/36 510 /proc/meminfo: memFree=606376/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=77028 CPUtime=10.96 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 20481 0 0 0 1093 3 0 0 25 0 1 0 67341230 78876672 18714 1283457024 134512640 136285277 4293544096 18446744073709551615 134650349 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 19257 18714 234 433 0 18822 0 Current children cumulated CPU time (s) 12.57 Current children cumulated vsize (KiB) 79624 [startup+25.5069 s] /proc/loadavg: 0.95 0.98 0.99 2/35 510 /proc/meminfo: memFree=606384/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=79268 CPUtime=23.75 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 21272 0 0 0 2372 3 0 0 25 0 1 0 67341230 81170432 19312 1283457024 134512640 136285277 4293544096 18446744073709551615 134650359 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 19817 19312 234 433 0 19382 0 Current children cumulated CPU time (s) 25.36 Current children cumulated vsize (KiB) 81864 [startup+51.1143 s] /proc/loadavg: 0.96 0.98 0.99 2/35 510 /proc/meminfo: memFree=588776/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=97940 CPUtime=49.34 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 25667 0 0 0 4930 4 0 0 25 0 1 0 67341230 100290560 23707 1283457024 134512640 136285277 4293544096 18446744073709551615 134966973 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 24485 23707 234 433 0 24050 0 Current children cumulated CPU time (s) 50.95 Current children cumulated vsize (KiB) 100536 [startup+102.307 s] /proc/loadavg: 0.98 0.98 0.99 2/35 510 /proc/meminfo: memFree=588652/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=97940 CPUtime=100.48 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 25667 0 0 0 10043 5 0 0 25 0 1 0 67341230 100290560 23707 1283457024 134512640 136285277 4293544096 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 24485 23707 234 433 0 24050 0 Current children cumulated CPU time (s) 102.09 Current children cumulated vsize (KiB) 100536 [startup+162.311 s] /proc/loadavg: 0.99 0.98 0.99 2/35 510 /proc/meminfo: memFree=587040/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=99668 CPUtime=160.46 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 26081 0 0 0 16041 5 0 0 25 0 1 0 67341230 102060032 24121 1283457024 134512640 136285277 4293544096 18446744073709551615 134964568 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 24917 24121 234 433 0 24482 0 Current children cumulated CPU time (s) 162.07 Current children cumulated vsize (KiB) 102264 [startup+222.306 s] /proc/loadavg: 0.99 0.98 0.99 2/35 510 /proc/meminfo: memFree=587164/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=99484 CPUtime=220.42 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 28109 0 0 0 22034 8 0 0 25 0 1 0 67341230 101871616 24063 1283457024 134512640 136285277 4293544096 18446744073709551615 134649439 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 24871 24063 234 433 0 24436 0 Current children cumulated CPU time (s) 222.03 Current children cumulated vsize (KiB) 102080 [startup+282.309 s] /proc/loadavg: 0.99 0.98 0.99 2/37 514 /proc/meminfo: memFree=586272/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=100340 CPUtime=280.37 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 29059 0 0 0 28027 10 0 0 25 0 1 0 67341230 102748160 24277 1283457024 134512640 136285277 4293544096 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 25085 24277 234 433 0 24650 0 Current children cumulated CPU time (s) 281.98 Current children cumulated vsize (KiB) 102936 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.41 s] /proc/loadavg: 0.99 0.98 0.99 2/37 515 /proc/meminfo: memFree=587264/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=98548 CPUtime=288.46 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 29856 0 0 0 28835 11 0 0 25 0 1 0 67341230 100913152 23860 1283457024 134512640 136285277 4293544096 18446744073709551615 134650371 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 24637 23860 234 433 0 24202 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 101144 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.41 s] /proc/loadavg: 0.99 0.98 0.99 2/37 515 /proc/meminfo: memFree=587264/1048576 swapFree=0/0 [pid=499] ppid=498 vsize=2596 CPUtime=1.61 /proc/499/stat : 499 (aspcud-1.5) S 498 499 19908 34817 19908 4202496 580 15594 0 0 0 1 155 5 16 0 1 0 67341229 2658304 298 1283457024 134512640 135304128 4288375712 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/499/statm: 649 298 251 194 0 36 0 [pid=508] ppid=499 vsize=98548 CPUtime=288.46 /proc/508/stat : 508 (clasp) R 499 499 19908 34817 19908 4202496 29856 0 0 0 28835 11 0 0 25 0 1 0 67341230 100913152 23860 1283457024 134512640 136285277 4293544096 18446744073709551615 134650371 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/508/statm: 24637 23860 234 433 0 24202 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 101144 Child status: 0 Real time (s): 290.446 CPU time (s): 290.126 CPU user time (s): 289.918 CPU system time (s): 0.208013 CPU usage (%): 99.89 Max. virtual memory (cumulated for all children) (KiB): 104512 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.918 system time used= 0.208013 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 49848 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= 675 involuntary context switches= 3994 runsolver used 0 second user time and 0 second system time The end