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/201109011757/aspcud-1.5/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//3e4f8550-0b33-11df-942d-00163e1d94dc.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/3e4f8550-0b33-11df-942d-00163e1d94dc.cudf.dudf-real.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-notuptodate,-removed,-changed 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.00 1.00 1.00 5/40 27417 /proc/meminfo: memFree=409724/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2592 CPUtime=0 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 373 0 0 0 0 0 0 0 20 0 1 0 72266618 2654208 280 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/27415/statm: 648 280 234 194 0 35 0 [pid=27416] ppid=27415 vsize=2592 CPUtime=0 /proc/27416/stat : 27416 (aspcud-1.5) R 27415 27415 22717 34817 22717 4202560 110 0 0 0 0 0 0 0 25 0 1 0 72266618 2654208 133 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/27416/statm: 648 133 86 194 0 35 0 [pid=27417] ppid=27416 vsize=2592 CPUtime=0 /proc/27417/stat : 27417 (aspcud-1.5) R 27416 27415 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72266618 2654208 47 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/27417/statm: 648 47 0 194 0 35 0 [startup+0.203362 s] /proc/loadavg: 1.00 1.00 1.00 5/40 27417 /proc/meminfo: memFree=409724/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=0 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.308191 s] /proc/loadavg: 1.00 1.00 1.00 5/40 27417 /proc/meminfo: memFree=409724/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=0 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.403368 s] /proc/loadavg: 1.00 1.00 1.00 5/40 27417 /proc/meminfo: memFree=409724/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=0 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.7074 s] /proc/loadavg: 1.00 1.00 1.00 5/40 27417 /proc/meminfo: memFree=409724/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=0 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.50743 s] /proc/loadavg: 1.00 1.00 1.00 2/42 27426 /proc/meminfo: memFree=372956/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=0 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 1519 0 0 0 0 0 0 25 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=1924 CPUtime=0 /proc/27424/stat : 27424 (clasp) S 27415 27415 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 72266619 1970176 159 1283457024 134512640 136285277 4293136448 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/27424/statm: 481 159 144 433 0 46 0 [pid=27425] ppid=27415 vsize=2584 CPUtime=0 /proc/27425/stat : 27425 (gringo) S 27415 27415 22717 34817 22717 4202496 405 0 0 0 0 0 0 0 25 0 1 0 72266619 2646016 272 1283457024 134512640 136933539 4287884208 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/27425/statm: 646 272 242 592 0 51 0 [pid=27426] ppid=27415 vsize=26168 CPUtime=1.32 /proc/27426/stat : 27426 (cudf2lp) R 27415 27415 22717 34817 22717 4202496 7650 0 0 0 128 4 0 0 25 0 1 0 72266619 26796032 6051 1283457024 134512640 135786343 4291942224 18446744073709551615 134796970 0 0 6 0 0 0 0 17 0 0 0 0 /proc/27426/statm: 6542 6051 128 311 0 6229 0 Current children cumulated CPU time (s) 1.32 Current children cumulated vsize (KiB) 33276 [startup+3.1047 s] /proc/loadavg: 1.00 1.00 1.00 2/42 27426 /proc/meminfo: memFree=340752/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.28 /proc/27415/stat : 27415 (aspcud-1.5) R 27414 27415 22717 34817 22717 4202496 581 17559 0 0 0 0 220 8 19 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=5752 CPUtime=0.47 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 1349 0 0 0 47 0 0 0 18 0 1 0 72266619 5890048 1215 1283457024 134512640 136285277 4293136448 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 1438 1215 234 433 0 1003 0 [pid=27425] ppid=27415 vsize=0 CPUtime=0.12 /proc/27425/stat : 27425 (gringo) Z 27415 27415 22717 34817 22717 4202508 1501 0 0 0 12 0 0 0 18 0 1 0 72266619 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/27425/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.87 Current children cumulated vsize (KiB) 8352 [startup+6.30539 s] /proc/loadavg: 1.00 1.00 1.00 2/40 27427 /proc/meminfo: memFree=379844/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=9864 CPUtime=3.67 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 2385 0 0 0 366 1 0 0 25 0 1 0 72266619 10100736 2251 1283457024 134512640 136285277 4293136448 18446744073709551615 134735675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 2466 2251 234 433 0 2031 0 Current children cumulated CPU time (s) 6.08 Current children cumulated vsize (KiB) 12464 [startup+12.7069 s] /proc/loadavg: 1.00 1.00 1.00 2/40 27427 /proc/meminfo: memFree=377364/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=11696 CPUtime=10.06 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 2939 0 0 0 1005 1 0 0 25 0 1 0 72266619 11976704 2718 1283457024 134512640 136285277 4293136448 18446744073709551615 134723297 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 2924 2718 234 433 0 2489 0 Current children cumulated CPU time (s) 12.47 Current children cumulated vsize (KiB) 14296 [startup+25.5098 s] /proc/loadavg: 1.00 1.00 1.00 2/40 27429 /proc/meminfo: memFree=376620/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=12080 CPUtime=22.85 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 3279 0 0 0 2283 2 0 0 25 0 1 0 72266619 12369920 2814 1283457024 134512640 136285277 4293136448 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 3020 2814 234 433 0 2585 0 Current children cumulated CPU time (s) 25.26 Current children cumulated vsize (KiB) 14680 [startup+51.1054 s] /proc/loadavg: 1.00 1.00 1.00 2/39 27430 /proc/meminfo: memFree=375644/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=13060 CPUtime=48.44 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 4032 0 0 0 4841 3 0 0 25 0 1 0 72266619 13373440 3059 1283457024 134512640 136285277 4293136448 18446744073709551615 134649408 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 3265 3059 234 433 0 2830 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 15660 [startup+102.306 s] /proc/loadavg: 1.00 1.00 1.00 2/39 27430 /proc/meminfo: memFree=373784/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=15552 CPUtime=99.6 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 4700 0 0 0 9957 3 0 0 25 0 1 0 72266619 15925248 3647 1283457024 134512640 136285277 4293136448 18446744073709551615 134686305 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 3888 3647 234 433 0 3453 0 Current children cumulated CPU time (s) 102.01 Current children cumulated vsize (KiB) 18152 [startup+162.308 s] /proc/loadavg: 1.00 1.00 1.00 2/38 27430 /proc/meminfo: memFree=371808/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=17420 CPUtime=159.55 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 5422 0 0 0 15951 4 0 0 25 0 1 0 72266619 17838080 4136 1283457024 134512640 136285277 4293136448 18446744073709551615 134735638 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 4355 4136 234 433 0 3920 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 20020 [startup+222.31 s] /proc/loadavg: 1.00 1.00 1.00 2/38 27430 /proc/meminfo: memFree=370196/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=19016 CPUtime=219.54 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 5869 0 0 0 21949 5 0 0 25 0 1 0 72266619 19472384 4536 1283457024 134512640 136285277 4293136448 18446744073709551615 134931890 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 4754 4536 234 433 0 4319 0 Current children cumulated CPU time (s) 221.95 Current children cumulated vsize (KiB) 21616 [startup+282.312 s] /proc/loadavg: 1.00 1.00 1.00 2/38 27430 /proc/meminfo: memFree=369824/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=19212 CPUtime=279.5 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 5982 0 0 0 27944 6 0 0 25 0 1 0 72266619 19673088 4585 1283457024 134512640 136285277 4293136448 18446744073709551615 134733705 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 4803 4585 234 433 0 4368 0 Current children cumulated CPU time (s) 281.91 Current children cumulated vsize (KiB) 21812 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.414 s] /proc/loadavg: 1.00 1.00 1.00 2/38 27430 /proc/meminfo: memFree=369824/1048576 swapFree=0/0 [pid=27415] ppid=27414 vsize=2600 CPUtime=2.41 /proc/27415/stat : 27415 (aspcud-1.5) S 27414 27415 22717 34817 22717 4202496 581 19060 0 0 0 0 233 8 16 0 1 0 72266618 2662400 299 1283457024 134512640 135304128 4289487968 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/27415/statm: 650 299 251 194 0 37 0 [pid=27424] ppid=27415 vsize=19212 CPUtime=287.59 /proc/27424/stat : 27424 (clasp) R 27415 27415 22717 34817 22717 4202496 5982 0 0 0 28753 6 0 0 25 0 1 0 72266619 19673088 4585 1283457024 134512640 136285277 4293136448 18446744073709551615 134733711 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/27424/statm: 4803 4585 234 433 0 4368 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 21812 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.435 CPU time (s): 290.046 CPU user time (s): 289.87 CPU system time (s): 0.176011 CPU usage (%): 99.8661 Max. virtual memory (cumulated for all children) (KiB): 62140 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.87 system time used= 0.176011 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 29161 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= 223 involuntary context switches= 3711 runsolver used 0 second user time and 0.008 second system time The end