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/56e31304-c17a-11df-b070-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//56e31304-c17a-11df-b070-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/56e31304-c17a-11df-b070-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 1.00 1.00 4/36 29464 /proc/meminfo: memFree=665724/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2588 CPUtime=0 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 374 0 0 0 0 0 0 0 25 0 1 0 65474323 2650112 280 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/29461/statm: 647 280 234 194 0 34 0 [pid=29462] ppid=29461 vsize=2588 CPUtime=0 /proc/29462/stat : 29462 (aspcud-1.5) S 29461 29461 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 25 0 1 0 65474323 2650112 134 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/29462/statm: 647 134 87 194 0 34 0 [pid=29463] ppid=29462 vsize=2588 CPUtime=0 /proc/29463/stat : 29463 (aspcud-1.5) R 29462 29461 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 65474323 2650112 151 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29463/statm: 647 151 104 194 0 34 0 [pid=29464] ppid=29463 vsize=2588 CPUtime=0 /proc/29464/stat : 29464 (aspcud-1.5) R 29463 29461 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 65474323 2650112 47 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/29464/statm: 647 47 0 194 0 34 0 [startup+0.162728 s] /proc/loadavg: 1.00 1.00 1.00 4/36 29464 /proc/meminfo: memFree=665724/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=0 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 1521 0 0 0 0 0 0 25 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.20652 s] /proc/loadavg: 1.00 1.00 1.00 4/36 29464 /proc/meminfo: memFree=665724/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=0 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 1521 0 0 0 0 0 0 25 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306478 s] /proc/loadavg: 1.00 1.00 1.00 4/36 29464 /proc/meminfo: memFree=665724/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=0 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 1521 0 0 0 0 0 0 25 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706548 s] /proc/loadavg: 1.00 1.00 1.00 4/36 29464 /proc/meminfo: memFree=665724/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=0 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 1521 0 0 0 0 0 0 25 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50655 s] /proc/loadavg: 1.00 1.00 1.00 2/37 29472 /proc/meminfo: memFree=626044/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=0 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 1521 0 0 0 0 0 0 25 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=1928 CPUtime=0.01 /proc/29470/stat : 29470 (clasp) S 29461 29461 19908 34817 19908 4202496 291 0 0 0 0 1 0 0 25 0 1 0 65474324 1974272 159 1283457024 134512640 136285277 4293786400 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/29470/statm: 482 159 144 433 0 47 0 [pid=29471] ppid=29461 vsize=2588 CPUtime=0 /proc/29471/stat : 29471 (gringo) S 29461 29461 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 65474324 2650112 272 1283457024 134512640 136933539 4290283008 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/29471/statm: 647 272 242 592 0 52 0 [pid=29472] ppid=29461 vsize=28300 CPUtime=1.25 /proc/29472/stat : 29472 (cudf2lp) R 29461 29461 19908 34817 19908 4202496 8229 0 0 0 123 2 0 0 25 0 1 0 65474324 28979200 6582 1283457024 134512640 135786343 4293282032 18446744073709551615 134616284 0 0 6 0 0 0 0 17 0 0 0 0 /proc/29472/statm: 7075 6582 128 311 0 6762 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 35412 [startup+3.11581 s] /proc/loadavg: 1.00 1.00 1.00 3/36 29472 /proc/meminfo: memFree=643008/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=4896 CPUtime=1.17 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 1139 0 0 0 116 1 0 0 19 0 1 0 65474324 5013504 1007 1283457024 134512640 136285277 4293786400 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 1224 1007 234 433 0 789 0 Current children cumulated CPU time (s) 2.87 Current children cumulated vsize (KiB) 7492 [startup+6.30636 s] /proc/loadavg: 1.08 1.02 1.01 2/35 29472 /proc/meminfo: memFree=641536/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=5112 CPUtime=4.37 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 1205 0 0 0 436 1 0 0 25 0 1 0 65474324 5234688 1073 1283457024 134512640 136285277 4293786400 18446744073709551615 134985191 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 1278 1073 234 433 0 843 0 Current children cumulated CPU time (s) 6.07 Current children cumulated vsize (KiB) 7708 [startup+12.7077 s] /proc/loadavg: 1.07 1.02 1.00 2/35 29472 /proc/meminfo: memFree=640668/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=5904 CPUtime=10.77 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 1394 0 0 0 1076 1 0 0 25 0 1 0 65474324 6045696 1246 1283457024 134512640 136285277 4293786400 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 1476 1246 234 433 0 1041 0 Current children cumulated CPU time (s) 12.47 Current children cumulated vsize (KiB) 8500 [startup+25.5101 s] /proc/loadavg: 1.06 1.01 1.00 2/35 29472 /proc/meminfo: memFree=640296/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=6380 CPUtime=23.56 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 1538 0 0 0 2355 1 0 0 25 0 1 0 65474324 6533120 1360 1283457024 134512640 136285277 4293786400 18446744073709551615 134960050 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 1595 1360 234 433 0 1160 0 Current children cumulated CPU time (s) 25.26 Current children cumulated vsize (KiB) 8976 [startup+51.1148 s] /proc/loadavg: 1.04 1.01 1.00 2/35 29472 /proc/meminfo: memFree=639428/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=7060 CPUtime=49.16 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 1868 0 0 0 4915 1 0 0 25 0 1 0 65474324 7229440 1538 1283457024 134512640 136285277 4293786400 18446744073709551615 134966710 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 1765 1538 234 433 0 1330 0 Current children cumulated CPU time (s) 50.86 Current children cumulated vsize (KiB) 9656 [startup+102.306 s] /proc/loadavg: 1.01 1.01 1.00 2/37 29477 /proc/meminfo: memFree=638288/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=8080 CPUtime=100.33 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 2315 0 0 0 10032 1 0 0 25 0 1 0 65474324 8273920 1796 1283457024 134512640 136285277 4293786400 18446744073709551615 134960068 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 2020 1796 234 433 0 1585 0 Current children cumulated CPU time (s) 102.03 Current children cumulated vsize (KiB) 10676 [startup+162.31 s] /proc/loadavg: 1.00 1.00 1.00 2/37 29482 /proc/meminfo: memFree=638040/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=8104 CPUtime=160.22 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 2348 0 0 0 16021 1 0 0 25 0 1 0 65474324 8298496 1821 1283457024 134512640 136285277 4293786400 18446744073709551615 134723310 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 2026 1821 234 433 0 1591 0 Current children cumulated CPU time (s) 161.92 Current children cumulated vsize (KiB) 10700 [startup+222.314 s] /proc/loadavg: 1.00 1.00 1.00 2/36 29483 /proc/meminfo: memFree=637808/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=8320 CPUtime=220.15 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 2657 0 0 0 22014 1 0 0 25 0 1 0 65474324 8519680 1875 1283457024 134512640 136285277 4293786400 18446744073709551615 134955168 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 2080 1875 234 433 0 1645 0 Current children cumulated CPU time (s) 221.85 Current children cumulated vsize (KiB) 10916 [startup+282.315 s] /proc/loadavg: 1.00 1.00 1.00 2/35 29483 /proc/meminfo: memFree=637816/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=8512 CPUtime=280.03 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 2711 0 0 0 28002 1 0 0 25 0 1 0 65474324 8716288 1923 1283457024 134512640 136285277 4293786400 18446744073709551615 135648483 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 2128 1923 234 433 0 1693 0 Current children cumulated CPU time (s) 281.73 Current children cumulated vsize (KiB) 11108 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.607 s] /proc/loadavg: 1.00 1.00 1.00 2/35 29483 /proc/meminfo: memFree=637816/1048576 swapFree=0/0 [pid=29461] ppid=29460 vsize=2596 CPUtime=1.7 /proc/29461/stat : 29461 (aspcud-1.5) S 29460 29461 19908 34817 19908 4202496 577 14835 0 0 0 0 166 4 17 0 1 0 65474323 2658304 299 1283457024 134512640 135304128 4294013184 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/29461/statm: 649 299 251 194 0 36 0 [pid=29470] ppid=29461 vsize=8512 CPUtime=288.32 /proc/29470/stat : 29470 (clasp) R 29461 29461 19908 34817 19908 4202496 2711 0 0 0 28831 1 0 0 25 0 1 0 65474324 8716288 1923 1283457024 134512640 136285277 4293786400 18446744073709551615 134960075 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/29470/statm: 2128 1923 234 433 0 1693 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 11108 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.627 CPU time (s): 290.05 CPU user time (s): 289.974 CPU system time (s): 0.076004 CPU usage (%): 99.8015 Max. virtual memory (cumulated for all children) (KiB): 51908 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.974 system time used= 0.076004 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 21659 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