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/201012070034/aspcud-trendy-1.3/randa223c3.cudf.impossible.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/impossible//randa223c3.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/randa223c3.cudf.impossible.result 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.11 1.13 1.06 2/44 735 /proc/meminfo: memFree=715248/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=3028 CPUtime=0 /proc/735/stat : 735 (runsolver) D 734 735 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 884641266 3100672 94 1283457024 134512640 134586868 4292658992 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/735/statm: 757 94 62 19 0 55 0 [startup+0.141379 s] /proc/loadavg: 1.11 1.13 1.06 2/44 735 /proc/meminfo: memFree=715248/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=0 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 2214 0 3 0 0 0 0 25 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.205381 s] /proc/loadavg: 1.11 1.13 1.06 2/44 735 /proc/meminfo: memFree=715248/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=0 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 2214 0 3 0 0 0 0 25 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.311294 s] /proc/loadavg: 1.11 1.13 1.06 2/44 735 /proc/meminfo: memFree=715248/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=0 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 2214 0 3 0 0 0 0 25 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.711367 s] /proc/loadavg: 1.11 1.13 1.06 2/44 735 /proc/meminfo: memFree=715248/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=0 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 2214 0 3 0 0 0 0 25 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.51162 s] /proc/loadavg: 1.26 1.16 1.07 2/48 749 /proc/meminfo: memFree=677184/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=0 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 2214 0 3 0 0 0 0 25 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=1864 CPUtime=0 /proc/747/stat : 747 (clasp) S 735 735 4159 34819 4229 4202496 269 0 15 0 0 0 0 0 24 0 1 0 884641270 1908736 152 1283457024 134512640 136223643 4288776288 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/747/statm: 466 152 138 418 0 46 0 [pid=748] ppid=735 vsize=2612 CPUtime=0.01 /proc/748/stat : 748 (gringo) S 735 735 4159 34819 4229 4202496 386 0 22 0 0 1 0 0 23 0 1 0 884641270 2674688 277 1283457024 134512640 136959103 4289211120 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/748/statm: 653 277 247 598 0 52 0 [pid=749] ppid=735 vsize=50480 CPUtime=1.27 /proc/749/stat : 749 (cudf2lp) R 735 735 4159 34819 4229 4202496 13951 0 14 0 124 3 0 0 25 0 1 0 884641270 51691520 11812 1283457024 134512640 135749571 4288772000 18446744073709551615 134568243 0 0 6 0 0 0 0 17 0 0 0 0 /proc/749/statm: 12620 11812 127 302 0 12316 0 Current children cumulated CPU time (s) 1.28 Current children cumulated vsize (KiB) 57552 [startup+3.11209 s] /proc/loadavg: 1.26 1.16 1.07 3/48 749 /proc/meminfo: memFree=642348/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=0 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 2214 0 3 0 0 0 0 25 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=18196 CPUtime=0.1 /proc/747/stat : 747 (clasp) S 735 735 4159 34819 4229 4202496 4993 0 18 0 6 4 0 0 18 0 1 0 884641270 18632704 4221 1283457024 134512640 136223643 4288776288 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/747/statm: 4549 4221 174 418 0 4129 0 [pid=748] ppid=735 vsize=27992 CPUtime=0.79 /proc/748/stat : 748 (gringo) R 735 735 4159 34819 4229 4202496 8552 0 22 0 76 3 0 0 18 0 1 0 884641270 28663808 4764 1283457024 134512640 136959103 4289211120 18446744073709551615 136202998 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/748/statm: 6998 4764 247 598 0 6397 0 [pid=749] ppid=735 vsize=62352 CPUtime=1.97 /proc/749/stat : 749 (cudf2lp) R 735 735 4159 34819 4229 4202496 18988 0 14 0 191 6 0 0 25 0 1 0 884641270 63848448 15187 1283457024 134512640 135749571 4288772000 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/749/statm: 15588 15187 129 302 0 15284 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 111136 [startup+6.30356 s] /proc/loadavg: 1.24 1.16 1.07 2/46 749 /proc/meminfo: memFree=658688/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=69684 CPUtime=1.36 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 20182 0 19 0 129 7 0 0 19 0 1 0 884641270 71356416 16073 1283457024 134512640 136223643 4288776288 18446744073709551615 134873938 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 17421 16073 214 418 0 17001 0 Current children cumulated CPU time (s) 6.05 Current children cumulated vsize (KiB) 72280 [startup+12.7155 s] /proc/loadavg: 1.22 1.16 1.07 2/46 749 /proc/meminfo: memFree=646784/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=68468 CPUtime=7.77 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 20219 0 19 0 770 7 0 0 25 0 1 0 884641270 70111232 15850 1283457024 134512640 136223643 4288776288 18446744073709551615 134924387 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 17117 15850 225 418 0 16697 0 Current children cumulated CPU time (s) 12.46 Current children cumulated vsize (KiB) 71064 [startup+25.5088 s] /proc/loadavg: 1.17 1.15 1.06 2/46 749 /proc/meminfo: memFree=646784/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=68468 CPUtime=20.58 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 20225 0 19 0 2051 7 0 0 25 0 1 0 884641270 70111232 15856 1283457024 134512640 136223643 4288776288 18446744073709551615 134711229 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 17117 15856 225 418 0 16697 0 Current children cumulated CPU time (s) 25.27 Current children cumulated vsize (KiB) 71064 [startup+51.1061 s] /proc/loadavg: 1.11 1.14 1.06 2/46 749 /proc/meminfo: memFree=628928/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=86800 CPUtime=46.16 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 24787 0 19 0 4605 11 0 0 25 0 1 0 884641270 88883200 20418 1283457024 134512640 136223643 4288776288 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 21700 20418 225 418 0 21280 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 89396 [startup+102.31 s] /proc/loadavg: 1.05 1.11 1.06 2/46 749 /proc/meminfo: memFree=567672/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=148052 CPUtime=97.33 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 40070 0 19 0 9712 21 0 0 25 0 1 0 884641270 151605248 35701 1283457024 134512640 136223643 4288776288 18446744073709551615 134931327 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 37013 35701 225 418 0 36593 0 Current children cumulated CPU time (s) 102.02 Current children cumulated vsize (KiB) 150648 [startup+162.307 s] /proc/loadavg: 1.02 1.09 1.05 2/46 749 /proc/meminfo: memFree=556460/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=160220 CPUtime=157.29 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 43295 0 19 0 15707 22 0 0 25 0 1 0 884641270 164065280 38718 1283457024 134512640 136223643 4288776288 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 40055 38718 225 418 0 39635 0 Current children cumulated CPU time (s) 161.98 Current children cumulated vsize (KiB) 162816 [startup+222.313 s] /proc/loadavg: 1.00 1.07 1.04 2/46 749 /proc/meminfo: memFree=538356/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=177016 CPUtime=217.24 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 47461 0 19 0 21700 24 0 0 25 0 1 0 884641270 181264384 42884 1283457024 134512640 136223643 4288776288 18446744073709551615 134924367 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 44254 42884 225 418 0 43834 0 Current children cumulated CPU time (s) 221.93 Current children cumulated vsize (KiB) 179612 [startup+282.311 s] /proc/loadavg: 1.00 1.06 1.04 2/46 749 /proc/meminfo: memFree=538604/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=175856 CPUtime=277.22 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 47482 0 19 0 27696 26 0 0 25 0 1 0 884641270 180076544 42638 1283457024 134512640 136223643 4288776288 18446744073709551615 134650929 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 43964 42638 225 418 0 43544 0 Current children cumulated CPU time (s) 281.91 Current children cumulated vsize (KiB) 178452 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.513 s] /proc/loadavg: 1.00 1.05 1.04 2/46 749 /proc/meminfo: memFree=538604/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=175856 CPUtime=285.41 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 47484 0 19 0 28515 26 0 0 25 0 1 0 884641270 180076544 42640 1283457024 134512640 136223643 4288776288 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 43964 42640 225 418 0 43544 0 Current children cumulated CPU time (s) 290.1 Current children cumulated vsize (KiB) 178452 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.513 s] /proc/loadavg: 1.00 1.05 1.04 2/46 749 /proc/meminfo: memFree=538604/1048576 swapFree=2077616/2097144 [pid=735] ppid=734 vsize=2596 CPUtime=4.69 /proc/735/stat : 735 (aspcud-trendy-1) S 734 735 4159 34819 4229 4202496 620 44648 0 40 0 0 447 22 18 0 1 0 884641266 2658304 299 1283457024 134512640 135304128 4293761280 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/735/statm: 649 299 253 194 0 35 0 [pid=747] ppid=735 vsize=175856 CPUtime=285.41 /proc/747/stat : 747 (clasp) R 735 735 4159 34819 4229 4202496 47484 0 19 0 28515 26 0 0 25 0 1 0 884641270 180076544 42640 1283457024 134512640 136223643 4288776288 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/747/statm: 43964 42640 225 418 0 43544 0 Current children cumulated CPU time (s) 290.1 Current children cumulated vsize (KiB) 178452 Child status: 0 Real time (s): 290.557 CPU time (s): 290.13 CPU user time (s): 289.63 CPU system time (s): 0.500031 CPU usage (%): 99.853 Max. virtual memory (cumulated for all children) (KiB): 179612 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.63 system time used= 0.500031 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 95379 page faults= 60 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 4040 involuntary context switches= 6854 runsolver used 0.004 second user time and 0 second system time The end