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/201108251442/aspcud-paranoid-1.5/rand662.cudf.dudf-random.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-random//rand662.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand662.cudf.dudf-random.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.50 1.39 1.19 6/37 20877 /proc/meminfo: memFree=305184/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=0.02 /proc/20861/stat : 20861 (aspcud-paranoid) R 20860 20861 4778 34817 4778 4202496 633 2934 0 0 0 0 0 2 25 0 1 0 11131655 2662400 298 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0 /proc/20861/statm: 650 298 250 194 0 37 0 [pid=20875] ppid=20861 vsize=2600 CPUtime=0 /proc/20875/stat : 20875 (aspcud-paranoid) R 20861 20861 4778 34817 4778 4202560 111 0 0 0 0 0 0 0 25 0 1 0 11131657 2662400 132 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0 /proc/20875/statm: 650 132 83 194 0 37 0 [pid=20876] ppid=20861 vsize=2600 CPUtime=0 /proc/20876/stat : 20876 (aspcud-paranoid) S 20861 20861 4778 34817 4778 4202560 111 0 0 0 0 0 0 0 25 0 1 0 11131657 2662400 132 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564457842 0 0 17 0 0 0 0 /proc/20876/statm: 650 132 83 194 0 37 0 [pid=20877] ppid=20861 vsize=2600 CPUtime=0 /proc/20877/stat : 20877 (aspcud-paranoid) R 20861 20861 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11131657 2662400 48 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0 /proc/20877/statm: 650 48 0 194 0 37 0 [startup+0.140156 s] /proc/loadavg: 1.50 1.39 1.19 6/37 20877 /proc/meminfo: memFree=305184/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=0.02 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 2934 0 0 0 0 0 2 25 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=1924 CPUtime=0 /proc/20875/stat : 20875 (clasp) S 20861 20861 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 11131657 1970176 159 1283457024 134512640 136285277 4290551216 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20875/statm: 481 159 144 433 0 46 0 [pid=20876] ppid=20861 vsize=2588 CPUtime=0 /proc/20876/stat : 20876 (gringo) S 20861 20861 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11131657 2650112 272 1283457024 134512640 136933539 4288885904 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20876/statm: 647 272 242 592 0 52 0 [pid=20877] ppid=20861 vsize=3944 CPUtime=0.1 /proc/20877/stat : 20877 (cudf2lp) R 20861 20861 4778 34817 4778 4202496 920 0 0 0 10 0 0 0 25 0 1 0 11131657 4038656 742 1283457024 134512640 135786343 4293339360 18446744073709551615 135208447 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20877/statm: 986 742 126 311 0 673 0 Current children cumulated CPU time (s) 0.12 Current children cumulated vsize (KiB) 11056 [startup+0.204286 s] /proc/loadavg: 1.50 1.39 1.19 6/37 20877 /proc/meminfo: memFree=305184/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=0.02 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 2934 0 0 0 0 0 2 25 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=1924 CPUtime=0 /proc/20875/stat : 20875 (clasp) S 20861 20861 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 11131657 1970176 159 1283457024 134512640 136285277 4290551216 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20875/statm: 481 159 144 433 0 46 0 [pid=20876] ppid=20861 vsize=2588 CPUtime=0 /proc/20876/stat : 20876 (gringo) S 20861 20861 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11131657 2650112 272 1283457024 134512640 136933539 4288885904 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20876/statm: 647 272 242 592 0 52 0 [pid=20877] ppid=20861 vsize=5356 CPUtime=0.17 /proc/20877/stat : 20877 (cudf2lp) R 20861 20861 4778 34817 4778 4202496 1326 0 0 0 17 0 0 0 25 0 1 0 11131657 5484544 1059 1283457024 134512640 135786343 4293339360 18446744073709551615 134924830 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20877/statm: 1339 1059 126 311 0 1026 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 12468 [startup+0.304196 s] /proc/loadavg: 1.50 1.39 1.19 6/37 20877 /proc/meminfo: memFree=305184/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=0.02 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 2934 0 0 0 0 0 2 25 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=1924 CPUtime=0 /proc/20875/stat : 20875 (clasp) S 20861 20861 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 11131657 1970176 159 1283457024 134512640 136285277 4290551216 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20875/statm: 481 159 144 433 0 46 0 [pid=20876] ppid=20861 vsize=2588 CPUtime=0 /proc/20876/stat : 20876 (gringo) S 20861 20861 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11131657 2650112 272 1283457024 134512640 136933539 4288885904 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20876/statm: 647 272 242 592 0 52 0 [pid=20877] ppid=20861 vsize=8372 CPUtime=0.26 /proc/20877/stat : 20877 (cudf2lp) R 20861 20861 4778 34817 4778 4202496 2158 0 0 0 26 0 0 0 25 0 1 0 11131657 8572928 1714 1283457024 134512640 135786343 4293339360 18446744073709551615 135044512 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20877/statm: 2093 1714 126 311 0 1780 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 15484 [startup+0.704206 s] /proc/loadavg: 1.50 1.39 1.19 6/37 20877 /proc/meminfo: memFree=305184/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=0.02 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 2934 0 0 0 0 0 2 25 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=1924 CPUtime=0 /proc/20875/stat : 20875 (clasp) S 20861 20861 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 11131657 1970176 159 1283457024 134512640 136285277 4290551216 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20875/statm: 481 159 144 433 0 46 0 [pid=20876] ppid=20861 vsize=2588 CPUtime=0 /proc/20876/stat : 20876 (gringo) S 20861 20861 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11131657 2650112 272 1283457024 134512640 136933539 4288885904 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20876/statm: 647 272 242 592 0 52 0 [pid=20877] ppid=20861 vsize=14524 CPUtime=0.62 /proc/20877/stat : 20877 (cudf2lp) R 20861 20861 4778 34817 4778 4202496 3960 0 0 0 62 0 0 0 25 0 1 0 11131657 14872576 3163 1283457024 134512640 135786343 4293339360 18446744073709551615 134633332 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20877/statm: 3631 3163 126 311 0 3318 0 Current children cumulated CPU time (s) 0.64 Current children cumulated vsize (KiB) 21636 [startup+1.50424 s] /proc/loadavg: 1.46 1.39 1.19 2/38 20878 /proc/meminfo: memFree=268080/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=0.02 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 2934 0 0 0 0 0 2 25 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=1924 CPUtime=0 /proc/20875/stat : 20875 (clasp) S 20861 20861 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 11131657 1970176 159 1283457024 134512640 136285277 4290551216 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/20875/statm: 481 159 144 433 0 46 0 [pid=20876] ppid=20861 vsize=2588 CPUtime=0 /proc/20876/stat : 20876 (gringo) S 20861 20861 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11131657 2650112 272 1283457024 134512640 136933539 4288885904 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/20876/statm: 647 272 242 592 0 52 0 [pid=20877] ppid=20861 vsize=25004 CPUtime=1.36 /proc/20877/stat : 20877 (cudf2lp) R 20861 20861 4778 34817 4778 4202496 7195 0 0 0 132 4 0 0 25 0 1 0 11131657 25604096 5596 1283457024 134512640 135786343 4293339360 18446744073709551615 134605792 0 0 6 0 0 0 0 17 0 0 0 0 /proc/20877/statm: 6251 5596 126 311 0 5938 0 Current children cumulated CPU time (s) 1.38 Current children cumulated vsize (KiB) 32116 [startup+3.10904 s] /proc/loadavg: 1.46 1.39 1.19 2/38 20878 /proc/meminfo: memFree=237604/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=2.24 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 15841 0 0 0 0 215 9 18 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=14936 CPUtime=0.06 /proc/20875/stat : 20875 (clasp) R 20861 20861 4778 34817 4778 4202496 4134 0 0 0 2 4 0 0 18 0 1 0 11131657 15294464 3343 1283457024 134512640 136285277 4290551216 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20875/statm: 3734 3343 177 433 0 3299 0 [pid=20876] ppid=20861 vsize=23484 CPUtime=0.58 /proc/20876/stat : 20876 (gringo) R 20861 20861 4778 34817 4778 4202496 6563 0 0 0 57 1 0 0 18 0 1 0 11131657 24047616 4611 1283457024 134512640 136933539 4288885904 18446744073709551615 136204829 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/20876/statm: 5871 4611 253 592 0 5276 0 Current children cumulated CPU time (s) 2.88 Current children cumulated vsize (KiB) 41020 Solver just ended. Dumping a history of the last processes samples [startup+3.20907 s] /proc/loadavg: 1.46 1.39 1.19 2/38 20878 /proc/meminfo: memFree=237604/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=2.24 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 15841 0 0 0 0 215 9 18 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=17312 CPUtime=0.08 /proc/20875/stat : 20875 (clasp) R 20861 20861 4778 34817 4778 4202496 4771 0 0 0 4 4 0 0 18 0 1 0 11131657 17727488 3980 1283457024 134512640 136285277 4290551216 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20875/statm: 4328 3980 177 433 0 3893 0 [pid=20876] ppid=20861 vsize=27152 CPUtime=0.66 /proc/20876/stat : 20876 (gringo) R 20861 20861 4778 34817 4778 4202496 7618 0 0 0 64 2 0 0 18 0 1 0 11131657 27803648 5537 1283457024 134512640 136933539 4288885904 18446744073709551615 134689093 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/20876/statm: 6788 5537 253 592 0 6193 0 Current children cumulated CPU time (s) 2.98 Current children cumulated vsize (KiB) 47064 [startup+4.00933 s] /proc/loadavg: 1.46 1.39 1.19 3/37 20878 /proc/meminfo: memFree=235264/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=3.26 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 26776 0 0 0 0 312 14 15 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=32356 CPUtime=0.53 /proc/20875/stat : 20875 (clasp) R 20861 20861 4778 34817 4778 4202496 9488 0 0 0 48 5 0 0 18 0 1 0 11131657 33132544 7816 1283457024 134512640 136285277 4290551216 18446744073709551615 134889053 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20875/statm: 8089 7816 218 433 0 7654 0 Current children cumulated CPU time (s) 3.79 Current children cumulated vsize (KiB) 34956 [startup+4.20939 s] /proc/loadavg: 1.46 1.39 1.19 3/37 20878 /proc/meminfo: memFree=235264/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=3.26 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 26776 0 0 0 0 312 14 15 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=31812 CPUtime=0.73 /proc/20875/stat : 20875 (clasp) R 20861 20861 4778 34817 4778 4202496 9508 0 0 0 68 5 0 0 18 0 1 0 11131657 32575488 7728 1283457024 134512640 136285277 4290551216 18446744073709551615 134931355 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20875/statm: 7953 7728 234 433 0 7518 0 Current children cumulated CPU time (s) 3.99 Current children cumulated vsize (KiB) 34412 [startup+4.30943 s] /proc/loadavg: 1.46 1.39 1.19 3/37 20878 /proc/meminfo: memFree=235264/1048576 swapFree=0/0 [pid=20861] ppid=20860 vsize=2600 CPUtime=3.26 /proc/20861/stat : 20861 (aspcud-paranoid) S 20860 20861 4778 34817 4778 4202496 659 26776 0 0 0 0 312 14 15 0 1 0 11131655 2662400 299 1283457024 134512640 135304128 4292523984 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/20861/statm: 650 299 251 194 0 37 0 [pid=20875] ppid=20861 vsize=31812 CPUtime=0.83 /proc/20875/stat : 20875 (clasp) R 20861 20861 4778 34817 4778 4202496 9508 0 0 0 78 5 0 0 18 0 1 0 11131657 32575488 7728 1283457024 134512640 136285277 4290551216 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/20875/statm: 7953 7728 234 433 0 7518 0 Current children cumulated CPU time (s) 4.09 Current children cumulated vsize (KiB) 34412 Child status: 0 Real time (s): 4.37122 CPU time (s): 4.16426 CPU user time (s): 3.93225 CPU system time (s): 0.232014 CPU usage (%): 95.2653 Max. virtual memory (cumulated for all children) (KiB): 68140 getrusage(RUSAGE_CHILDREN,...) data: user time used= 3.93224 system time used= 0.232014 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 40893 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= 1276 involuntary context switches= 1023 runsolver used 0 second user time and 0.004 second system time The end