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/201108241238/aspcud-trendy-1.5/rand315.cudf.s-e.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e/rand315.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand315.cudf.s-e.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.07 1.03 1.00 5/36 8416 /proc/meminfo: memFree=531628/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2588 CPUtime=0 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 2102625 2650112 279 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/8414/statm: 647 279 234 194 0 34 0 [pid=8415] ppid=8414 vsize=2588 CPUtime=0 /proc/8415/stat : 8415 (aspcud-trendy-1) R 8414 8414 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 2102625 2650112 132 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/8415/statm: 647 132 86 194 0 34 0 [pid=8416] ppid=8415 vsize=2588 CPUtime=0 /proc/8416/stat : 8416 (aspcud-trendy-1) R 8415 8414 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2102625 2650112 46 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/8416/statm: 647 46 0 194 0 34 0 [startup+0.19761 s] /proc/loadavg: 1.07 1.03 1.00 5/36 8416 /proc/meminfo: memFree=531628/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=0 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 622 2228 0 0 0 0 0 0 25 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.207601 s] /proc/loadavg: 1.07 1.03 1.00 5/36 8416 /proc/meminfo: memFree=531628/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=0 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 622 2228 0 0 0 0 0 0 25 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.307637 s] /proc/loadavg: 1.07 1.03 1.00 5/36 8416 /proc/meminfo: memFree=531628/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=0 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 622 2228 0 0 0 0 0 0 25 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.7077 s] /proc/loadavg: 1.07 1.03 1.00 5/36 8416 /proc/meminfo: memFree=531628/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=0 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 622 2228 0 0 0 0 0 0 25 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50787 s] /proc/loadavg: 1.07 1.03 1.00 3/37 8428 /proc/meminfo: memFree=514124/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=17488 CPUtime=0.1 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 4555 0 0 0 10 0 0 0 18 0 1 0 2102626 17907712 4037 1283457024 134512640 136285277 4292919280 18446744073709551615 134803409 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 4372 4037 189 433 0 3937 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 20084 [startup+3.10817 s] /proc/loadavg: 1.07 1.03 1.00 2/36 8428 /proc/meminfo: memFree=513148/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=19656 CPUtime=1.7 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 5583 0 0 0 170 0 0 0 20 0 1 0 2102626 20127744 4702 1283457024 134512640 136285277 4292919280 18446744073709551615 134967001 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 4914 4702 234 433 0 4479 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 22252 [startup+6.30894 s] /proc/loadavg: 1.06 1.03 1.00 2/36 8428 /proc/meminfo: memFree=513164/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=19920 CPUtime=4.9 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 5634 0 0 0 490 0 0 0 25 0 1 0 2102626 20398080 4753 1283457024 134512640 136285277 4292919280 18446744073709551615 135641548 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 4980 4753 234 433 0 4545 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 22516 [startup+12.7107 s] /proc/loadavg: 1.06 1.03 1.00 2/36 8428 /proc/meminfo: memFree=507832/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=25452 CPUtime=11.3 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 7032 0 0 0 1128 2 0 0 25 0 1 0 2102626 26062848 6151 1283457024 134512640 136285277 4292919280 18446744073709551615 134959927 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 6363 6151 234 433 0 5928 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 28048 [startup+25.504 s] /proc/loadavg: 1.04 1.03 1.00 2/36 8428 /proc/meminfo: memFree=501384/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=31976 CPUtime=24.08 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 8654 0 0 0 2406 2 0 0 25 0 1 0 2102626 32743424 7773 1283457024 134512640 136285277 4292919280 18446744073709551615 134959696 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 7994 7773 234 433 0 7559 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 34572 Solver just ended. Dumping a history of the last processes samples [startup+25.6041 s] /proc/loadavg: 1.04 1.03 1.00 2/36 8428 /proc/meminfo: memFree=501384/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=31976 CPUtime=24.18 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 8654 0 0 0 2416 2 0 0 25 0 1 0 2102626 32743424 7773 1283457024 134512640 136285277 4292919280 18446744073709551615 134615068 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 7994 7773 234 433 0 7559 0 Current children cumulated CPU time (s) 25.56 Current children cumulated vsize (KiB) 34572 [startup+27.2045 s] /proc/loadavg: 1.04 1.03 1.00 2/36 8428 /proc/meminfo: memFree=499772/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=37000 CPUtime=25.78 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 9909 0 0 0 2576 2 0 0 25 0 1 0 2102626 37888000 9028 1283457024 134512640 136285277 4292919280 18446744073709551615 134960178 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 9250 9028 234 433 0 8815 0 Current children cumulated CPU time (s) 27.16 Current children cumulated vsize (KiB) 39596 [startup+28.0047 s] /proc/loadavg: 1.04 1.03 1.00 2/36 8428 /proc/meminfo: memFree=495184/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=39904 CPUtime=26.58 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 10628 0 0 0 2656 2 0 0 25 0 1 0 2102626 40861696 9747 1283457024 134512640 136285277 4292919280 18446744073709551615 134733718 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 9976 9747 234 433 0 9541 0 Current children cumulated CPU time (s) 27.96 Current children cumulated vsize (KiB) 42500 [startup+28.4048 s] /proc/loadavg: 1.04 1.03 1.00 2/36 8428 /proc/meminfo: memFree=495184/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=41356 CPUtime=26.98 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 10982 0 0 0 2696 2 0 0 25 0 1 0 2102626 42348544 10101 1283457024 134512640 136285277 4292919280 18446744073709551615 134959543 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 10339 10101 234 433 0 9904 0 Current children cumulated CPU time (s) 28.36 Current children cumulated vsize (KiB) 43952 [startup+28.6056 s] /proc/loadavg: 1.04 1.03 1.00 2/36 8428 /proc/meminfo: memFree=513412/1048576 swapFree=0/0 [pid=8414] ppid=8413 vsize=2596 CPUtime=1.38 /proc/8414/stat : 8414 (aspcud-trendy-1) S 8413 8414 1511 34817 1511 4202496 623 15329 0 0 0 0 134 4 15 0 1 0 2102625 2658304 298 1283457024 134512640 135304128 4286732880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8414/statm: 649 298 251 194 0 36 0 [pid=8426] ppid=8414 vsize=19236 CPUtime=27.18 /proc/8426/stat : 8426 (clasp) R 8414 8414 1511 34817 1511 4202496 11050 0 0 0 2715 3 0 0 25 0 1 0 2102626 19697664 4610 1283457024 134512640 136285277 4292919280 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/8426/statm: 4809 4610 241 433 0 4374 0 Current children cumulated CPU time (s) 28.56 Current children cumulated vsize (KiB) 21832 Child status: 0 Real time (s): 28.6328 CPU time (s): 28.6098 CPU user time (s): 28.5098 CPU system time (s): 0.100006 CPU usage (%): 99.9196 Max. virtual memory (cumulated for all children) (KiB): 44084 getrusage(RUSAGE_CHILDREN,...) data: user time used= 28.5098 system time used= 0.100006 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 30605 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= 1052 involuntary context switches= 1363 runsolver used 0 second user time and 0 second system time The end