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/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/6b0d1da0-c730-11df-a7c5-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.08 1.06 1.01 5/37 30046 /proc/meminfo: memFree=580704/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2588 CPUtime=0 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 65766424 2650112 280 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/30044/statm: 647 280 234 194 0 34 0 [pid=30045] ppid=30044 vsize=2588 CPUtime=0 /proc/30045/stat : 30045 (aspcud-1.5) R 30044 30044 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 65766424 2650112 133 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/30045/statm: 647 133 86 194 0 34 0 [pid=30046] ppid=30045 vsize=2588 CPUtime=0 /proc/30046/stat : 30046 (aspcud-1.5) R 30045 30044 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 65766424 2650112 47 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/30046/statm: 647 47 0 194 0 34 0 [startup+0.16265 s] /proc/loadavg: 1.08 1.06 1.01 5/37 30046 /proc/meminfo: memFree=580704/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=0 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206638 s] /proc/loadavg: 1.08 1.06 1.01 5/37 30046 /proc/meminfo: memFree=580704/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=0 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306645 s] /proc/loadavg: 1.08 1.06 1.01 5/37 30046 /proc/meminfo: memFree=580704/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=0 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.70667 s] /proc/loadavg: 1.08 1.06 1.01 5/37 30046 /proc/meminfo: memFree=580704/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=0 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50672 s] /proc/loadavg: 1.08 1.06 1.01 2/39 30055 /proc/meminfo: memFree=540768/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=0 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 1521 0 0 0 0 0 0 25 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=1924 CPUtime=0 /proc/30053/stat : 30053 (clasp) S 30044 30044 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 65766425 1970176 159 1283457024 134512640 136285277 4292726736 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/30053/statm: 481 159 144 433 0 46 0 [pid=30054] ppid=30044 vsize=2580 CPUtime=0 /proc/30054/stat : 30054 (gringo) S 30044 30044 19908 34817 19908 4202496 403 0 0 0 0 0 0 0 25 0 1 0 65766425 2641920 271 1283457024 134512640 136933539 4291641168 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/30054/statm: 645 271 242 592 0 50 0 [pid=30055] ppid=30044 vsize=27968 CPUtime=1.26 /proc/30055/stat : 30055 (cudf2lp) R 30044 30044 19908 34817 19908 4202496 8262 0 0 0 124 2 0 0 25 0 1 0 65766425 28639232 6518 1283457024 134512640 135786343 4292727232 18446744073709551615 134566172 0 0 6 0 0 0 0 17 0 0 0 0 /proc/30055/statm: 6992 6518 128 311 0 6679 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 35068 [startup+3.10659 s] /proc/loadavg: 1.15 1.07 1.01 3/38 30055 /proc/meminfo: memFree=556080/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=6156 CPUtime=1.08 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 1461 0 0 0 108 0 0 0 19 0 1 0 65766425 6303744 1329 1283457024 134512640 136285277 4292726736 18446744073709551615 134723341 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 1539 1329 234 433 0 1104 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 8752 [startup+6.30704 s] /proc/loadavg: 1.15 1.07 1.01 2/37 30055 /proc/meminfo: memFree=553492/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=7024 CPUtime=4.28 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 1679 0 0 0 428 0 0 0 25 0 1 0 65766425 7192576 1547 1283457024 134512640 136285277 4292726736 18446744073709551615 134734701 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 1756 1547 234 433 0 1321 0 Current children cumulated CPU time (s) 6.06 Current children cumulated vsize (KiB) 9620 [startup+12.708 s] /proc/loadavg: 1.13 1.07 1.01 2/37 30056 /proc/meminfo: memFree=553368/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=7024 CPUtime=10.68 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 1679 0 0 0 1068 0 0 0 25 0 1 0 65766425 7192576 1547 1283457024 134512640 136285277 4292726736 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 1756 1547 234 433 0 1321 0 Current children cumulated CPU time (s) 12.46 Current children cumulated vsize (KiB) 9620 [startup+25.51 s] /proc/loadavg: 1.11 1.07 1.01 2/37 30057 /proc/meminfo: memFree=552376/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=8080 CPUtime=23.46 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 1925 0 0 0 2346 0 0 0 25 0 1 0 65766425 8273920 1793 1283457024 134512640 136285277 4292726736 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 2020 1793 234 433 0 1585 0 Current children cumulated CPU time (s) 25.24 Current children cumulated vsize (KiB) 10676 [startup+51.1151 s] /proc/loadavg: 1.07 1.06 1.01 2/37 30060 /proc/meminfo: memFree=551260/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=9048 CPUtime=49.05 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 2199 0 0 0 4905 0 0 0 25 0 1 0 65766425 9265152 2056 1283457024 134512640 136285277 4292726736 18446744073709551615 134735702 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 2262 2056 234 433 0 1827 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 11644 [startup+102.305 s] /proc/loadavg: 1.03 1.05 1.00 2/36 30060 /proc/meminfo: memFree=550160/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=10160 CPUtime=100.22 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 2544 0 0 0 10021 1 0 0 25 0 1 0 65766425 10403840 2336 1283457024 134512640 136285277 4292726736 18446744073709551615 134966985 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 2540 2336 234 433 0 2105 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 12756 [startup+162.308 s] /proc/loadavg: 1.01 1.04 1.00 2/35 30060 /proc/meminfo: memFree=549424/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=10964 CPUtime=160.21 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 2772 0 0 0 16020 1 0 0 25 0 1 0 65766425 11227136 2537 1283457024 134512640 136285277 4292726736 18446744073709551615 134960037 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 2741 2537 234 433 0 2306 0 Current children cumulated CPU time (s) 161.99 Current children cumulated vsize (KiB) 13560 [startup+222.311 s] /proc/loadavg: 1.00 1.03 1.00 2/35 30060 /proc/meminfo: memFree=548432/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=12000 CPUtime=220.15 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 3106 0 0 0 22014 1 0 0 25 0 1 0 65766425 12288000 2786 1283457024 134512640 136285277 4292726736 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 3000 2786 234 433 0 2565 0 Current children cumulated CPU time (s) 221.93 Current children cumulated vsize (KiB) 14596 [startup+282.305 s] /proc/loadavg: 1.00 1.02 1.00 2/35 30060 /proc/meminfo: memFree=548184/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=12032 CPUtime=280.12 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 3259 0 0 0 28011 1 0 0 25 0 1 0 65766425 12320768 2804 1283457024 134512640 136285277 4292726736 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 3008 2804 234 433 0 2573 0 Current children cumulated CPU time (s) 281.9 Current children cumulated vsize (KiB) 14628 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.506 s] /proc/loadavg: 1.00 1.02 1.00 2/35 30060 /proc/meminfo: memFree=547936/1048576 swapFree=0/0 [pid=30044] ppid=30043 vsize=2596 CPUtime=1.78 /proc/30044/stat : 30044 (aspcud-1.5) S 30043 30044 19908 34817 19908 4202496 583 15693 0 0 0 0 175 3 16 0 1 0 65766424 2658304 299 1283457024 134512640 135304128 4294353232 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30044/statm: 649 299 251 194 0 36 0 [pid=30053] ppid=30044 vsize=12428 CPUtime=288.31 /proc/30053/stat : 30053 (clasp) R 30044 30044 19908 34817 19908 4202496 3344 0 0 0 28830 1 0 0 25 0 1 0 65766425 12726272 2889 1283457024 134512640 136285277 4292726736 18446744073709551615 134931329 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30053/statm: 3107 2889 234 433 0 2672 0 Current children cumulated CPU time (s) 290.09 Current children cumulated vsize (KiB) 15024 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.527 CPU time (s): 290.13 CPU user time (s): 290.066 CPU system time (s): 0.064004 CPU usage (%): 99.8633 Max. virtual memory (cumulated for all children) (KiB): 51072 getrusage(RUSAGE_CHILDREN,...) data: user time used= 290.066 system time used= 0.064004 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 23162 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= 209 involuntary context switches= 3706 runsolver used 0 second user time and 0.012 second system time The end