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/cff22854-9512-11e0-8001-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//cff22854-9512-11e0-8001-00163e1e087d.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/cff22854-9512-11e0-8001-00163e1e087d.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.27 1.18 1.07 5/35 1412 /proc/meminfo: memFree=165576/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2592 CPUtime=0 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 18 0 1 0 67636653 2654208 280 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/1410/statm: 648 280 234 194 0 35 0 [pid=1411] ppid=1410 vsize=2592 CPUtime=0 /proc/1411/stat : 1411 (aspcud-1.5) R 1410 1410 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 67636653 2654208 133 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/1411/statm: 648 133 86 194 0 35 0 [pid=1412] ppid=1411 vsize=2592 CPUtime=0 /proc/1412/stat : 1412 (aspcud-1.5) R 1411 1410 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67636653 2654208 47 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/1412/statm: 648 47 0 194 0 35 0 [startup+0.158986 s] /proc/loadavg: 1.27 1.18 1.07 5/35 1412 /proc/meminfo: memFree=165576/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=0 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.207011 s] /proc/loadavg: 1.27 1.18 1.07 5/35 1412 /proc/meminfo: memFree=165576/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=0 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.306986 s] /proc/loadavg: 1.27 1.18 1.07 5/35 1412 /proc/meminfo: memFree=165576/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=0 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+0.710644 s] /proc/loadavg: 1.27 1.18 1.07 5/35 1412 /proc/meminfo: memFree=165576/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=0 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2600 [startup+1.51574 s] /proc/loadavg: 1.25 1.18 1.07 2/37 1421 /proc/meminfo: memFree=127896/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=0 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=1924 CPUtime=0 /proc/1419/stat : 1419 (clasp) S 1410 1410 19908 34817 19908 4202496 292 0 0 0 0 0 0 0 25 0 1 0 67636654 1970176 159 1283457024 134512640 136285277 4287347376 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/1419/statm: 481 159 144 433 0 46 0 [pid=1420] ppid=1410 vsize=2584 CPUtime=0 /proc/1420/stat : 1420 (gringo) S 1410 1410 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 67636654 2646016 271 1283457024 134512640 136933539 4290735728 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/1420/statm: 646 271 242 592 0 51 0 [pid=1421] ppid=1410 vsize=37964 CPUtime=1.31 /proc/1421/stat : 1421 (cudf2lp) R 1410 1410 19908 34817 19908 4202496 10583 0 0 0 121 10 0 0 25 0 1 0 67636654 38875136 8984 1283457024 134512640 135786343 4287347520 18446744073709551615 134554202 0 0 6 0 0 0 0 17 0 0 0 0 /proc/1421/statm: 9491 8984 135 311 0 9178 0 Current children cumulated CPU time (s) 1.31 Current children cumulated vsize (KiB) 45072 [startup+3.10605 s] /proc/loadavg: 1.25 1.18 1.07 3/36 1421 /proc/meminfo: memFree=144120/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=7128 CPUtime=1.25 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 1687 0 0 0 122 3 0 0 19 0 1 0 67636654 7299072 1551 1283457024 134512640 136285277 4287347376 18446744073709551615 134735675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 1782 1551 234 433 0 1347 0 Current children cumulated CPU time (s) 2.89 Current children cumulated vsize (KiB) 9728 [startup+6.3065 s] /proc/loadavg: 1.25 1.18 1.07 2/35 1421 /proc/meminfo: memFree=141284/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=7656 CPUtime=4.45 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 1865 0 0 0 442 3 0 0 25 0 1 0 67636654 7839744 1709 1283457024 134512640 136285277 4287347376 18446744073709551615 134960178 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 1914 1709 234 433 0 1479 0 Current children cumulated CPU time (s) 6.09 Current children cumulated vsize (KiB) 10256 [startup+12.7079 s] /proc/loadavg: 1.21 1.17 1.07 2/35 1421 /proc/meminfo: memFree=140788/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=9232 CPUtime=10.84 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 2313 0 0 0 1080 4 0 0 25 0 1 0 67636654 9453568 2100 1283457024 134512640 136285277 4287347376 18446744073709551615 134985188 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 2308 2100 234 433 0 1873 0 Current children cumulated CPU time (s) 12.48 Current children cumulated vsize (KiB) 11832 [startup+25.5107 s] /proc/loadavg: 1.18 1.16 1.07 2/35 1421 /proc/meminfo: memFree=139176/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=9760 CPUtime=23.64 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 2600 0 0 0 2360 4 0 0 25 0 1 0 67636654 9994240 2234 1283457024 134512640 136285277 4287347376 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 2440 2234 234 433 0 2005 0 Current children cumulated CPU time (s) 25.28 Current children cumulated vsize (KiB) 12360 [startup+51.1158 s] /proc/loadavg: 1.11 1.15 1.06 2/35 1421 /proc/meminfo: memFree=138184/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=10368 CPUtime=49.21 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 2760 0 0 0 4917 4 0 0 25 0 1 0 67636654 10616832 2386 1283457024 134512640 136285277 4287347376 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 2592 2386 234 433 0 2157 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 12968 [startup+102.308 s] /proc/loadavg: 1.04 1.12 1.06 2/35 1421 /proc/meminfo: memFree=137936/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=10636 CPUtime=100.36 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 3196 0 0 0 10032 4 0 0 25 0 1 0 67636654 10891264 2453 1283457024 134512640 136285277 4287347376 18446744073709551615 134733707 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 2659 2453 234 433 0 2224 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 13236 [startup+162.311 s] /proc/loadavg: 1.01 1.10 1.05 2/37 1427 /proc/meminfo: memFree=136796/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=11516 CPUtime=160.33 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 4370 0 0 0 16027 6 0 0 25 0 1 0 67636654 11792384 2671 1283457024 134512640 136285277 4287347376 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 2879 2671 234 433 0 2444 0 Current children cumulated CPU time (s) 161.97 Current children cumulated vsize (KiB) 14116 [startup+222.309 s] /proc/loadavg: 1.00 1.08 1.05 2/36 1432 /proc/meminfo: memFree=136564/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=11944 CPUtime=219.98 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 4944 0 0 0 21992 6 0 0 25 0 1 0 67636654 12230656 2778 1283457024 134512640 136285277 4287347376 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 2986 2778 234 433 0 2551 0 Current children cumulated CPU time (s) 221.62 Current children cumulated vsize (KiB) 14544 [startup+282.313 s] /proc/loadavg: 1.00 1.06 1.04 2/35 1432 /proc/meminfo: memFree=136448/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=12556 CPUtime=279.88 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 5519 0 0 0 27980 8 0 0 25 0 1 0 67636654 12857344 2914 1283457024 134512640 136285277 4287347376 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 3139 2914 234 433 0 2704 0 Current children cumulated CPU time (s) 281.52 Current children cumulated vsize (KiB) 15156 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.814 s] /proc/loadavg: 1.00 1.06 1.04 2/35 1432 /proc/meminfo: memFree=136448/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=12276 CPUtime=288.39 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 5531 0 0 0 28831 8 0 0 25 0 1 0 67636654 12570624 2861 1283457024 134512640 136285277 4287347376 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 3069 2861 234 433 0 2634 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 14876 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.814 s] /proc/loadavg: 1.00 1.06 1.04 2/35 1432 /proc/meminfo: memFree=136448/1048576 swapFree=0/0 [pid=1410] ppid=1409 vsize=2600 CPUtime=1.64 /proc/1410/stat : 1410 (aspcud-1.5) S 1409 1410 19908 34817 19908 4202496 581 14837 0 0 0 0 152 12 17 0 1 0 67636653 2662400 299 1283457024 134512640 135304128 4289324176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1410/statm: 650 299 251 194 0 37 0 [pid=1419] ppid=1410 vsize=12276 CPUtime=288.39 /proc/1419/stat : 1419 (clasp) R 1410 1410 19908 34817 19908 4202496 5531 0 0 0 28831 8 0 0 25 0 1 0 67636654 12570624 2861 1283457024 134512640 136285277 4287347376 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1419/statm: 3069 2861 234 433 0 2634 0 Current children cumulated CPU time (s) 290.03 Current children cumulated vsize (KiB) 14876 Child status: 0 Real time (s): 290.836 CPU time (s): 290.058 CPU user time (s): 289.834 CPU system time (s): 0.224014 CPU usage (%): 99.7326 Max. virtual memory (cumulated for all children) (KiB): 50484 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.834 system time used= 0.224014 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 24505 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= 189 involuntary context switches= 3718 runsolver used 0 second user time and 0.008 second system time The end