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/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/7c834c0e-51b8-11e0-a49e-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.12 1.11 1.04 5/36 30750 /proc/meminfo: memFree=712808/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2588 CPUtime=0 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 372 0 0 0 0 0 0 0 18 0 1 0 66175979 2650112 279 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/30748/statm: 647 279 234 194 0 34 0 [pid=30749] ppid=30748 vsize=2588 CPUtime=0 /proc/30749/stat : 30749 (aspcud-1.5) R 30748 30748 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 66175980 2650112 132 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/30749/statm: 647 132 86 194 0 34 0 [pid=30750] ppid=30749 vsize=2588 CPUtime=0 /proc/30750/stat : 30750 (aspcud-1.5) R 30749 30748 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 66175980 2650112 46 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/30750/statm: 647 46 0 194 0 34 0 [startup+0.15432 s] /proc/loadavg: 1.12 1.11 1.04 5/36 30750 /proc/meminfo: memFree=712808/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=0 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 1521 0 0 0 0 0 0 25 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206311 s] /proc/loadavg: 1.12 1.11 1.04 5/36 30750 /proc/meminfo: memFree=712808/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=0 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 1521 0 0 0 0 0 0 25 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306319 s] /proc/loadavg: 1.12 1.11 1.04 5/36 30750 /proc/meminfo: memFree=712808/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=0 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 1521 0 0 0 0 0 0 25 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706343 s] /proc/loadavg: 1.12 1.11 1.04 5/36 30750 /proc/meminfo: memFree=712808/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=0 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 1521 0 0 0 0 0 0 25 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50701 s] /proc/loadavg: 1.12 1.11 1.04 2/38 30759 /proc/meminfo: memFree=673376/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=0 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 1521 0 0 0 0 0 0 25 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=2472 CPUtime=0 /proc/30757/stat : 30757 (clasp) S 30748 30748 19908 34817 19908 4202496 455 0 0 0 0 0 0 0 18 0 1 0 66175981 2531328 323 1283457024 134512640 136285277 4289893664 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/30757/statm: 618 323 176 433 0 183 0 [pid=30758] ppid=30748 vsize=3592 CPUtime=0.02 /proc/30758/stat : 30758 (gringo) S 30748 30748 19908 34817 19908 4202496 630 0 0 0 2 0 0 0 18 0 1 0 66175981 3678208 465 1283457024 134512640 136933539 4287273760 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/30758/statm: 898 465 242 592 0 303 0 [pid=30759] ppid=30748 vsize=14792 CPUtime=1.31 /proc/30759/stat : 30759 (cudf2lp) R 30748 30748 19908 34817 19908 4202496 10541 0 0 0 124 7 0 0 25 0 1 0 66175981 15147008 3522 1283457024 134512640 135786343 4294130096 18446744073709551615 135191367 0 0 6 0 0 0 0 17 0 0 0 0 /proc/30759/statm: 3698 3522 139 311 0 3385 0 Current children cumulated CPU time (s) 1.33 Current children cumulated vsize (KiB) 23452 [startup+3.10725 s] /proc/loadavg: 1.19 1.13 1.04 3/37 30759 /proc/meminfo: memFree=693788/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=3636 CPUtime=1.56 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 820 0 0 0 156 0 0 0 20 0 1 0 66175981 3723264 688 1283457024 134512640 136285277 4289893664 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 909 688 233 433 0 474 0 Current children cumulated CPU time (s) 2.92 Current children cumulated vsize (KiB) 6232 [startup+6.30898 s] /proc/loadavg: 1.19 1.13 1.04 2/36 30759 /proc/meminfo: memFree=693424/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=4164 CPUtime=4.75 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 949 0 0 0 475 0 0 0 25 0 1 0 66175981 4263936 817 1283457024 134512640 136285277 4289893664 18446744073709551615 134735647 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1041 817 234 433 0 606 0 Current children cumulated CPU time (s) 6.11 Current children cumulated vsize (KiB) 6760 [startup+12.7104 s] /proc/loadavg: 1.16 1.12 1.04 2/36 30759 /proc/meminfo: memFree=693060/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=4372 CPUtime=11.14 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1000 0 0 0 1114 0 0 0 25 0 1 0 66175981 4476928 868 1283457024 134512640 136285277 4289893664 18446744073709551615 134963355 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1093 868 234 433 0 658 0 Current children cumulated CPU time (s) 12.5 Current children cumulated vsize (KiB) 6968 [startup+25.5127 s] /proc/loadavg: 1.13 1.12 1.04 2/36 30759 /proc/meminfo: memFree=692564/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=4828 CPUtime=23.94 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1121 0 0 0 2394 0 0 0 25 0 1 0 66175981 4943872 989 1283457024 134512640 136285277 4289893664 18446744073709551615 134735727 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1207 989 234 433 0 772 0 Current children cumulated CPU time (s) 25.3 Current children cumulated vsize (KiB) 7424 [startup+51.1075 s] /proc/loadavg: 1.09 1.11 1.04 2/35 30759 /proc/meminfo: memFree=692324/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=4940 CPUtime=49.52 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1188 0 0 0 4952 0 0 0 25 0 1 0 66175981 5058560 1030 1283457024 134512640 136285277 4289893664 18446744073709551615 134734216 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1235 1030 234 433 0 800 0 Current children cumulated CPU time (s) 50.88 Current children cumulated vsize (KiB) 7536 [startup+102.308 s] /proc/loadavg: 1.03 1.09 1.04 2/35 30759 /proc/meminfo: memFree=692076/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=5332 CPUtime=100.69 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1305 0 0 0 10069 0 0 0 25 0 1 0 66175981 5459968 1108 1283457024 134512640 136285277 4289893664 18446744073709551615 134959776 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1333 1108 234 433 0 898 0 Current children cumulated CPU time (s) 102.05 Current children cumulated vsize (KiB) 7928 [startup+162.309 s] /proc/loadavg: 1.01 1.07 1.03 2/35 30759 /proc/meminfo: memFree=691704/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=5632 CPUtime=160.67 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1386 0 0 0 16067 0 0 0 25 0 1 0 66175981 5767168 1186 1283457024 134512640 136285277 4289893664 18446744073709551615 134615133 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1408 1186 234 433 0 973 0 Current children cumulated CPU time (s) 162.03 Current children cumulated vsize (KiB) 8228 [startup+222.311 s] /proc/loadavg: 1.00 1.05 1.02 2/35 30759 /proc/meminfo: memFree=691580/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=5632 CPUtime=220.66 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1396 0 0 0 22064 2 0 0 25 0 1 0 66175981 5767168 1196 1283457024 134512640 136285277 4289893664 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1408 1196 234 433 0 973 0 Current children cumulated CPU time (s) 222.02 Current children cumulated vsize (KiB) 8228 [startup+282.312 s] /proc/loadavg: 1.00 1.04 1.02 2/37 30761 /proc/meminfo: memFree=691432/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=5700 CPUtime=280.64 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1411 0 0 0 28062 2 0 0 25 0 1 0 66175981 5836800 1211 1283457024 134512640 136285277 4289893664 18446744073709551615 134734762 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1425 1211 234 433 0 990 0 Current children cumulated CPU time (s) 282 Current children cumulated vsize (KiB) 8296 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.314 s] /proc/loadavg: 1.00 1.04 1.02 2/37 30762 /proc/meminfo: memFree=691432/1048576 swapFree=0/0 [pid=30748] ppid=30747 vsize=2596 CPUtime=1.36 /proc/30748/stat : 30748 (aspcud-1.5) S 30747 30748 19908 34817 19908 4202496 575 13079 0 0 0 0 129 7 17 0 1 0 66175979 2658304 298 1283457024 134512640 135304128 4291317360 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/30748/statm: 649 298 251 194 0 36 0 [pid=30757] ppid=30748 vsize=5700 CPUtime=288.64 /proc/30757/stat : 30757 (clasp) R 30748 30748 19908 34817 19908 4202496 1411 0 0 0 28862 2 0 0 25 0 1 0 66175981 5836800 1211 1283457024 134512640 136285277 4289893664 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/30757/statm: 1425 1211 234 433 0 990 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 8296 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.334 CPU time (s): 290.034 CPU user time (s): 289.918 CPU system time (s): 0.116007 CPU usage (%): 99.8967 Max. virtual memory (cumulated for all children) (KiB): 42456 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.918 system time used= 0.116007 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 18613 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= 158 involuntary context switches= 3622 runsolver used 0 second user time and 0.012 second system time The end