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/rand496.cudf.s-e-l-s-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand496.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand496.cudf.s-e-l-s-s.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.21 1.15 1.05 5/36 7654 /proc/meminfo: memFree=579308/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2588 CPUtime=0 /proc/7653/stat : 7653 (aspcud-trendy-1) R 7652 7653 1511 34817 1511 4202496 366 0 0 0 0 0 0 0 25 0 1 0 1776008 2650112 279 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/7653/statm: 647 279 234 194 0 34 0 [pid=7654] ppid=7653 vsize=2588 CPUtime=0 /proc/7654/stat : 7654 (aspcud-trendy-1) R 7653 7653 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1776009 2650112 45 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/7654/statm: 647 45 0 194 0 34 0 [startup+0.115231 s] /proc/loadavg: 1.21 1.15 1.05 5/36 7654 /proc/meminfo: memFree=579308/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=0.01 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 617 2231 0 0 0 0 1 0 25 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.205243 s] /proc/loadavg: 1.21 1.15 1.05 5/36 7654 /proc/meminfo: memFree=579308/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=0.01 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 617 2231 0 0 0 0 1 0 25 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.305252 s] /proc/loadavg: 1.21 1.15 1.05 5/36 7654 /proc/meminfo: memFree=579308/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=0.01 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 617 2231 0 0 0 0 1 0 25 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.705314 s] /proc/loadavg: 1.21 1.15 1.05 5/36 7654 /proc/meminfo: memFree=579308/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=0.01 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 617 2231 0 0 0 0 1 0 25 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50541 s] /proc/loadavg: 1.20 1.14 1.05 2/39 7667 /proc/meminfo: memFree=558300/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=0.01 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 617 2231 0 0 0 0 1 0 25 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=1928 CPUtime=0 /proc/7665/stat : 7665 (clasp) S 7653 7653 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 1776010 1974272 159 1283457024 134512640 136285277 4291686080 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/7665/statm: 482 159 144 433 0 47 0 [pid=7666] ppid=7653 vsize=2584 CPUtime=0 /proc/7666/stat : 7666 (gringo) S 7653 7653 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 1776010 2646016 272 1283457024 134512640 136933539 4292409328 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7666/statm: 646 272 242 592 0 51 0 [pid=7667] ppid=7653 vsize=40664 CPUtime=1.5 /proc/7667/stat : 7667 (cudf2lp) R 7653 7653 1511 34817 1511 4202496 11713 0 0 0 146 4 0 0 25 0 1 0 1776010 41639936 8803 1283457024 134512640 135786343 4287630208 18446744073709551615 134614701 0 0 6 0 0 0 0 17 0 0 0 0 /proc/7667/statm: 10166 8803 126 311 0 9853 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 47772 [startup+3.10572 s] /proc/loadavg: 1.20 1.14 1.05 2/39 7667 /proc/meminfo: memFree=524200/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=0.01 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 617 2231 0 0 0 0 1 0 25 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=17860 CPUtime=0.04 /proc/7665/stat : 7665 (clasp) S 7653 7653 1511 34817 1511 4202496 4882 0 0 0 4 0 0 0 18 0 1 0 1776010 18288640 4092 1283457024 134512640 136285277 4291686080 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/7665/statm: 4465 4092 177 433 0 4030 0 [pid=7666] ppid=7653 vsize=22180 CPUtime=0.8 /proc/7666/stat : 7666 (gringo) S 7653 7653 1511 34817 1511 4202496 6942 0 0 0 77 3 0 0 18 0 1 0 1776010 22712320 4670 1283457024 134512640 136933539 4292409328 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/7666/statm: 5545 4670 242 592 0 4950 0 [pid=7667] ppid=7653 vsize=46944 CPUtime=2.24 /proc/7667/stat : 7667 (cudf2lp) R 7653 7653 1511 34817 1511 4202496 16200 0 0 0 218 6 0 0 25 0 1 0 1776010 48070656 11463 1283457024 134512640 135786343 4287630208 18446744073709551615 135191532 0 0 6 0 0 0 0 17 0 0 0 0 /proc/7667/statm: 11736 11463 138 311 0 11423 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 89580 [startup+6.30627 s] /proc/loadavg: 1.20 1.14 1.05 2/37 7667 /proc/meminfo: memFree=523488/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=56160 CPUtime=2.06 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 17411 0 0 0 202 4 0 0 20 0 1 0 1776010 57507840 13788 1283457024 134512640 136285277 4291686080 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 14040 13788 234 433 0 13605 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 58756 [startup+12.7058 s] /proc/loadavg: 1.16 1.14 1.04 2/37 7668 /proc/meminfo: memFree=524372/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=56160 CPUtime=8.46 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 17437 0 0 0 842 4 0 0 25 0 1 0 1776010 57507840 13814 1283457024 134512640 136285277 4291686080 18446744073709551615 134985090 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 14040 13814 234 433 0 13605 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 58756 [startup+25.5089 s] /proc/loadavg: 1.14 1.13 1.04 2/37 7669 /proc/meminfo: memFree=469440/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=113280 CPUtime=21.22 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 31687 0 0 0 2110 12 0 0 25 0 1 0 1776010 115998720 28064 1283457024 134512640 136285277 4291686080 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 28320 28064 234 433 0 27885 0 Current children cumulated CPU time (s) 25.44 Current children cumulated vsize (KiB) 115876 [startup+51.1057 s] /proc/loadavg: 1.09 1.12 1.04 2/36 7671 /proc/meminfo: memFree=435728/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=145232 CPUtime=46.79 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 39691 0 0 0 4663 16 0 0 25 0 1 0 1776010 148717568 36068 1283457024 134512640 136285277 4291686080 18446744073709551615 134725844 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 36308 36068 234 433 0 35873 0 Current children cumulated CPU time (s) 51.01 Current children cumulated vsize (KiB) 147828 [startup+102.309 s] /proc/loadavg: 1.03 1.10 1.04 2/36 7671 /proc/meminfo: memFree=362320/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=218712 CPUtime=97.96 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 58009 0 0 0 9771 25 0 0 25 0 1 0 1776010 223961088 54386 1283457024 134512640 136285277 4291686080 18446744073709551615 134733705 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 54678 54386 234 433 0 54243 0 Current children cumulated CPU time (s) 102.18 Current children cumulated vsize (KiB) 221308 [startup+162.305 s] /proc/loadavg: 1.01 1.08 1.03 2/35 7671 /proc/meminfo: memFree=299584/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=281300 CPUtime=157.89 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 73669 0 0 0 15757 32 0 0 25 0 1 0 1776010 288051200 70046 1283457024 134512640 136285277 4291686080 18446744073709551615 134723347 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 70325 70046 234 433 0 69890 0 Current children cumulated CPU time (s) 162.11 Current children cumulated vsize (KiB) 283896 [startup+222.305 s] /proc/loadavg: 1.00 1.06 1.02 2/35 7671 /proc/meminfo: memFree=267840/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=313128 CPUtime=217.84 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 81602 0 0 0 21742 42 0 0 25 0 1 0 1776010 320643072 77979 1283457024 134512640 136285277 4291686080 18446744073709551615 134734701 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 78282 77979 234 433 0 77847 0 Current children cumulated CPU time (s) 222.06 Current children cumulated vsize (KiB) 315724 [startup+282.312 s] /proc/loadavg: 1.00 1.05 1.02 2/35 7671 /proc/meminfo: memFree=79112/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=505076 CPUtime=277.77 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 129706 0 0 0 27700 77 0 0 25 0 1 0 1776010 517197824 125842 1283457024 134512640 136285277 4291686080 18446744073709551615 134931352 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 126269 125842 234 433 0 125834 0 Current children cumulated CPU time (s) 281.99 Current children cumulated vsize (KiB) 507672 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.404 s] /proc/loadavg: 1.00 1.05 1.02 2/35 7671 /proc/meminfo: memFree=43276/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=538020 CPUtime=285.86 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 138003 0 0 0 28504 82 0 0 25 0 1 0 1776010 550932480 133982 1283457024 134512640 136285277 4291686080 18446744073709551615 134669904 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 134505 133982 234 433 0 134070 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 540616 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.404 s] /proc/loadavg: 1.00 1.05 1.02 2/35 7671 /proc/meminfo: memFree=43276/1048576 swapFree=0/0 [pid=7653] ppid=7652 vsize=2596 CPUtime=4.22 /proc/7653/stat : 7653 (aspcud-trendy-1) S 7652 7653 1511 34817 1511 4202496 618 38155 0 0 0 0 400 22 18 0 1 0 1776008 2658304 298 1283457024 134512640 135304128 4291403456 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/7653/statm: 649 298 251 194 0 36 0 [pid=7665] ppid=7653 vsize=538020 CPUtime=285.86 /proc/7665/stat : 7665 (clasp) R 7653 7653 1511 34817 1511 4202496 138003 0 0 0 28504 82 0 0 25 0 1 0 1776010 550932480 133982 1283457024 134512640 136285277 4291686080 18446744073709551615 134669904 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/7665/statm: 134505 133982 234 433 0 134070 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 540616 Child status: 0 Real time (s): 290.459 CPU time (s): 290.142 CPU user time (s): 289.054 CPU system time (s): 1.08807 CPU usage (%): 99.8908 Max. virtual memory (cumulated for all children) (KiB): 540616 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.054 system time used= 1.08807 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 180496 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= 2964 involuntary context switches= 5799 runsolver used 0 second user time and 0 second system time The end