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/d1583bd8-d489-11df-9a24-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//d1583bd8-d489-11df-9a24-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/d1583bd8-d489-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: 1.00 0.99 0.99 3/36 1932 /proc/meminfo: memFree=536916/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2588 CPUtime=0 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 374 0 0 0 0 0 0 0 25 0 1 0 67925366 2650112 280 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/1929/statm: 647 280 234 194 0 34 0 [pid=1930] ppid=1929 vsize=2588 CPUtime=0 /proc/1930/stat : 1930 (aspcud-1.5) S 1929 1929 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 25 0 1 0 67925366 2650112 134 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/1930/statm: 647 134 87 194 0 34 0 [pid=1931] ppid=1930 vsize=2588 CPUtime=0 /proc/1931/stat : 1931 (aspcud-1.5) R 1930 1929 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 67925366 2650112 151 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/1931/statm: 647 151 104 194 0 34 0 [pid=1932] ppid=1931 vsize=2588 CPUtime=0 /proc/1932/stat : 1932 (aspcud-1.5) R 1931 1929 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67925366 2650112 47 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/1932/statm: 647 47 0 194 0 34 0 [startup+0.106048 s] /proc/loadavg: 1.00 0.99 0.99 3/36 1932 /proc/meminfo: memFree=536916/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=0 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206056 s] /proc/loadavg: 1.00 0.99 0.99 3/36 1932 /proc/meminfo: memFree=536916/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=0 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306062 s] /proc/loadavg: 1.00 0.99 0.99 3/36 1932 /proc/meminfo: memFree=536916/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=0 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706087 s] /proc/loadavg: 1.00 0.99 0.99 3/36 1932 /proc/meminfo: memFree=536916/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=0 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50745 s] /proc/loadavg: 1.00 0.99 0.99 1/37 1940 /proc/meminfo: memFree=497364/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=0 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=1924 CPUtime=0 /proc/1938/stat : 1938 (clasp) S 1929 1929 19908 34817 19908 4202496 292 0 0 0 0 0 0 0 25 0 1 0 67925367 1970176 159 1283457024 134512640 136285277 4290399648 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/1938/statm: 481 159 144 433 0 46 0 [pid=1939] ppid=1929 vsize=2588 CPUtime=0 /proc/1939/stat : 1939 (gringo) S 1929 1929 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 67925367 2650112 272 1283457024 134512640 136933539 4289965488 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/1939/statm: 647 272 242 592 0 52 0 [pid=1940] ppid=1929 vsize=36548 CPUtime=1.26 /proc/1940/stat : 1940 (cudf2lp) R 1929 1929 19908 34817 19908 4202496 10338 0 0 0 124 2 0 0 25 0 1 0 67925367 37425152 8593 1283457024 134512640 135786343 4294427136 18446744073709551615 135052137 0 0 6 0 0 0 0 17 0 0 0 0 /proc/1940/statm: 9137 8593 135 311 0 8824 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 43656 [startup+3.10765 s] /proc/loadavg: 1.00 0.99 0.99 3/36 1940 /proc/meminfo: memFree=515272/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=3860 CPUtime=1.28 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 886 0 0 0 128 0 0 0 19 0 1 0 67925367 3952640 753 1283457024 134512640 136285277 4290399648 18446744073709551615 134960080 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 965 753 233 433 0 530 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 6456 [startup+6.30831 s] /proc/loadavg: 1.00 0.99 0.99 2/35 1940 /proc/meminfo: memFree=514916/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=4084 CPUtime=4.48 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 988 0 0 0 448 0 0 0 25 0 1 0 67925367 4182016 815 1283457024 134512640 136285277 4290399648 18446744073709551615 134930827 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1021 815 234 433 0 586 0 Current children cumulated CPU time (s) 6.06 Current children cumulated vsize (KiB) 6680 [startup+12.7098 s] /proc/loadavg: 1.00 0.99 0.99 2/35 1940 /proc/meminfo: memFree=514668/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=4276 CPUtime=10.89 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1014 0 0 0 1089 0 0 0 25 0 1 0 67925367 4378624 841 1283457024 134512640 136285277 4290399648 18446744073709551615 134649414 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1069 841 234 433 0 634 0 Current children cumulated CPU time (s) 12.47 Current children cumulated vsize (KiB) 6872 [startup+25.5124 s] /proc/loadavg: 1.00 0.99 0.99 2/35 1940 /proc/meminfo: memFree=514296/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=4612 CPUtime=23.67 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1106 0 0 0 2367 0 0 0 25 0 1 0 67925367 4722688 933 1283457024 134512640 136285277 4290399648 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1153 933 234 433 0 718 0 Current children cumulated CPU time (s) 25.25 Current children cumulated vsize (KiB) 7208 [startup+51.1081 s] /proc/loadavg: 1.00 0.99 0.99 2/37 1943 /proc/meminfo: memFree=513776/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=4876 CPUtime=49.25 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1168 0 0 0 4925 0 0 0 25 0 1 0 67925367 4993024 995 1283457024 134512640 136285277 4290399648 18446744073709551615 134733718 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1219 995 234 433 0 784 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 7472 [startup+102.309 s] /proc/loadavg: 1.00 0.99 0.99 2/37 1949 /proc/meminfo: memFree=513652/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=4876 CPUtime=100.44 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1168 0 0 0 10042 2 0 0 25 0 1 0 67925367 4993024 995 1283457024 134512640 136285277 4290399648 18446744073709551615 134948733 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1219 995 234 433 0 784 0 Current children cumulated CPU time (s) 102.02 Current children cumulated vsize (KiB) 7472 [startup+162.311 s] /proc/loadavg: 1.00 0.99 0.99 2/36 1951 /proc/meminfo: memFree=513420/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=5156 CPUtime=160.41 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1253 0 0 0 16039 2 0 0 25 0 1 0 67925367 5279744 1080 1283457024 134512640 136285277 4290399648 18446744073709551615 134627806 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1289 1080 234 433 0 854 0 Current children cumulated CPU time (s) 161.99 Current children cumulated vsize (KiB) 7752 [startup+222.313 s] /proc/loadavg: 1.00 0.99 0.99 2/35 1951 /proc/meminfo: memFree=513428/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=5156 CPUtime=220.36 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1253 0 0 0 22034 2 0 0 25 0 1 0 67925367 5279744 1080 1283457024 134512640 136285277 4290399648 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1289 1080 234 433 0 854 0 Current children cumulated CPU time (s) 221.94 Current children cumulated vsize (KiB) 7752 [startup+282.31 s] /proc/loadavg: 1.00 0.99 0.99 2/35 1951 /proc/meminfo: memFree=513428/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=5156 CPUtime=280.37 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1253 0 0 0 28034 3 0 0 25 0 1 0 67925367 5279744 1080 1283457024 134512640 136285277 4290399648 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1289 1080 234 433 0 854 0 Current children cumulated CPU time (s) 281.95 Current children cumulated vsize (KiB) 7752 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.412 s] /proc/loadavg: 1.00 0.99 0.99 2/35 1951 /proc/meminfo: memFree=513428/1048576 swapFree=0/0 [pid=1929] ppid=1928 vsize=2596 CPUtime=1.58 /proc/1929/stat : 1929 (aspcud-1.5) S 1928 1929 19908 34817 19908 4202496 581 14397 0 0 0 0 154 4 17 0 1 0 67925366 2658304 299 1283457024 134512640 135304128 4292249424 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1929/statm: 649 299 251 194 0 36 0 [pid=1938] ppid=1929 vsize=5156 CPUtime=288.46 /proc/1938/stat : 1938 (clasp) R 1929 1929 19908 34817 19908 4202496 1255 0 0 0 28843 3 0 0 25 0 1 0 67925367 5279744 1082 1283457024 134512640 136285277 4290399648 18446744073709551615 134733809 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1938/statm: 1289 1082 234 433 0 854 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 7752 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.432 CPU time (s): 290.078 CPU user time (s): 289.978 CPU system time (s): 0.100006 CPU usage (%): 99.8781 Max. virtual memory (cumulated for all children) (KiB): 49728 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.978 system time used= 0.100006 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 19794 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= 172 involuntary context switches= 3692 runsolver used 0 second user time and 0 second system time The end