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/rand348.cudf.s-e-l-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s/rand348.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand348.cudf.s-e-l-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.04 1.03 1.00 5/36 9769 /proc/meminfo: memFree=514160/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2584 CPUtime=0 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 2278894 2646016 279 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/9766/statm: 646 279 234 194 0 33 0 [pid=9767] ppid=9766 vsize=2584 CPUtime=0 /proc/9767/stat : 9767 (aspcud-trendy-1) S 9766 9766 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 2278894 2646016 133 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/9767/statm: 646 133 87 194 0 33 0 [pid=9768] ppid=9767 vsize=2584 CPUtime=0 /proc/9768/stat : 9768 (aspcud-trendy-1) R 9767 9766 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 2278894 2646016 150 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/9768/statm: 646 150 104 194 0 33 0 [pid=9769] ppid=9768 vsize=2584 CPUtime=0 /proc/9769/stat : 9769 (aspcud-trendy-1) R 9768 9766 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2278894 2646016 46 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/9769/statm: 646 46 0 194 0 33 0 [startup+0.15355 s] /proc/loadavg: 1.04 1.03 1.00 5/36 9769 /proc/meminfo: memFree=514160/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=0 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 616 2233 0 0 0 0 0 0 25 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.203555 s] /proc/loadavg: 1.04 1.03 1.00 5/36 9769 /proc/meminfo: memFree=514160/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=0 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 616 2233 0 0 0 0 0 0 25 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.313602 s] /proc/loadavg: 1.04 1.03 1.00 5/36 9769 /proc/meminfo: memFree=514160/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=0 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 616 2233 0 0 0 0 0 0 25 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.71369 s] /proc/loadavg: 1.04 1.03 1.00 5/36 9769 /proc/meminfo: memFree=514160/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=0 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 616 2233 0 0 0 0 0 0 25 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.51388 s] /proc/loadavg: 1.04 1.03 1.00 2/37 9780 /proc/meminfo: memFree=493556/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=0 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 616 2233 0 0 0 0 0 0 25 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=1924 CPUtime=0 /proc/9778/stat : 9778 (clasp) S 9766 9766 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 2278895 1970176 159 1283457024 134512640 136285277 4288859152 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/9778/statm: 481 159 144 433 0 46 0 [pid=9779] ppid=9766 vsize=2584 CPUtime=0 /proc/9779/stat : 9779 (gringo) S 9766 9766 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 2278895 2646016 272 1283457024 134512640 136933539 4287408944 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/9779/statm: 646 272 242 592 0 51 0 [pid=9780] ppid=9766 vsize=40448 CPUtime=1.49 /proc/9780/stat : 9780 (cudf2lp) R 9766 9766 1511 34817 1511 4202496 11648 0 0 0 146 3 0 0 25 0 1 0 2278895 41418752 8738 1283457024 134512640 135786343 4294797904 18446744073709551615 134568912 0 0 6 0 0 0 0 17 0 0 0 0 /proc/9780/statm: 10112 8738 131 311 0 9799 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 47548 [startup+3.10427 s] /proc/loadavg: 1.04 1.03 1.00 3/37 9780 /proc/meminfo: memFree=459456/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=2.17 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 17929 0 0 0 0 210 7 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=19312 CPUtime=0.11 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 5318 0 0 0 8 3 0 0 18 0 1 0 2278895 19775488 4528 1283457024 134512640 136285277 4288859152 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 4828 4528 177 433 0 4393 0 [pid=9779] ppid=9766 vsize=32776 CPUtime=0.79 /proc/9779/stat : 9779 (gringo) R 9766 9766 1511 34817 1511 4202496 9674 0 0 0 76 3 0 0 18 0 1 0 2278895 33562624 5991 1283457024 134512640 136933539 4287408944 18446744073709551615 134611933 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9779/statm: 8194 5991 253 592 0 7599 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 54680 [startup+6.30512 s] /proc/loadavg: 1.12 1.04 1.01 2/35 9780 /proc/meminfo: memFree=462596/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=52784 CPUtime=2.33 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 15983 0 0 0 227 6 0 0 20 0 1 0 2278895 54050816 12960 1283457024 134512640 136285277 4288859152 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 13196 12960 234 433 0 12761 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 55376 [startup+12.7064 s] /proc/loadavg: 1.11 1.04 1.01 2/35 9780 /proc/meminfo: memFree=453304/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=67264 CPUtime=8.72 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 19582 0 0 0 866 6 0 0 25 0 1 0 2278895 68878336 16559 1283457024 134512640 136285277 4288859152 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 16816 16559 234 433 0 16381 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 69856 [startup+25.5094 s] /proc/loadavg: 1.08 1.04 1.00 2/35 9780 /proc/meminfo: memFree=433340/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=82684 CPUtime=21.51 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 23464 0 0 0 2141 10 0 0 25 0 1 0 2278895 84668416 20441 1283457024 134512640 136285277 4288859152 18446744073709551615 134650846 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 20671 20441 234 433 0 20236 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 85276 [startup+51.1043 s] /proc/loadavg: 1.05 1.04 1.00 2/35 9780 /proc/meminfo: memFree=407796/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=108240 CPUtime=47.09 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 29837 0 0 0 4696 13 0 0 25 0 1 0 2278895 110837760 26814 1283457024 134512640 136285277 4288859152 18446744073709551615 134733771 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 27060 26814 234 433 0 26625 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 110832 [startup+102.307 s] /proc/loadavg: 1.02 1.03 1.00 2/35 9780 /proc/meminfo: memFree=377912/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=138008 CPUtime=98.24 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 37438 0 0 0 9809 15 0 0 25 0 1 0 2278895 141320192 34256 1283457024 134512640 136285277 4288859152 18446744073709551615 134966799 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 34502 34256 234 433 0 34067 0 Current children cumulated CPU time (s) 102.19 Current children cumulated vsize (KiB) 140600 [startup+162.313 s] /proc/loadavg: 1.01 1.02 1.00 2/37 9784 /proc/meminfo: memFree=336472/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=179204 CPUtime=158.16 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 47723 0 0 0 15795 21 0 0 25 0 1 0 2278895 183504896 44541 1283457024 134512640 136285277 4288859152 18446744073709551615 134931382 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 44801 44541 234 433 0 44366 0 Current children cumulated CPU time (s) 162.11 Current children cumulated vsize (KiB) 181796 [startup+222.311 s] /proc/loadavg: 1.00 1.02 1.00 2/37 9791 /proc/meminfo: memFree=171552/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=344536 CPUtime=218.11 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 89084 0 0 0 21773 38 0 0 25 0 1 0 2278895 352804864 85797 1283457024 134512640 136285277 4288859152 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 86134 85797 234 433 0 85699 0 Current children cumulated CPU time (s) 222.06 Current children cumulated vsize (KiB) 347128 [startup+282.31 s] /proc/loadavg: 1.00 1.01 1.00 2/36 9791 /proc/meminfo: memFree=95928/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=419732 CPUtime=278.06 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 108019 0 0 0 27756 50 0 0 25 0 1 0 2278895 429805568 104596 1283457024 134512640 136285277 4288859152 18446744073709551615 134669906 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 104933 104596 234 433 0 104498 0 Current children cumulated CPU time (s) 282.01 Current children cumulated vsize (KiB) 422324 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.312 s] /proc/loadavg: 1.00 1.01 1.00 2/36 9791 /proc/meminfo: memFree=95804/1048576 swapFree=0/0 [pid=9766] ppid=9765 vsize=2592 CPUtime=3.95 /proc/9766/stat : 9766 (aspcud-trendy-1) S 9765 9766 1511 34817 1511 4202496 617 36916 0 0 0 0 380 15 18 0 1 0 2278894 2654208 298 1283457024 134512640 135304128 4293357728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9766/statm: 648 298 251 194 0 35 0 [pid=9778] ppid=9766 vsize=419732 CPUtime=286.06 /proc/9778/stat : 9778 (clasp) R 9766 9766 1511 34817 1511 4202496 108019 0 0 0 28556 50 0 0 25 0 1 0 2278895 429805568 104596 1283457024 134512640 136285277 4288859152 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/9778/statm: 104933 104596 234 433 0 104498 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 422324 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.359 CPU time (s): 290.066 CPU user time (s): 289.382 CPU system time (s): 0.684042 CPU usage (%): 99.899 Max. virtual memory (cumulated for all children) (KiB): 422324 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.382 system time used= 0.684042 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 149213 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= 2668 involuntary context switches= 5568 runsolver used 0 second user time and 0.012 second system time The end