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/rand149.cudf.s-e-l-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s/rand149.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand149.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.06 1.03 0.76 5/40 2320 /proc/meminfo: memFree=744028/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2584 CPUtime=0 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 688428 2646016 279 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/2318/statm: 646 279 234 194 0 33 0 [pid=2319] ppid=2318 vsize=2584 CPUtime=0 /proc/2319/stat : 2319 (aspcud-trendy-1) R 2318 2318 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 688429 2646016 132 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/2319/statm: 646 132 86 194 0 33 0 [pid=2320] ppid=2319 vsize=2584 CPUtime=0 /proc/2320/stat : 2320 (aspcud-trendy-1) R 2319 2318 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 688429 2646016 46 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/2320/statm: 646 46 0 194 0 33 0 [startup+0.168099 s] /proc/loadavg: 1.06 1.03 0.76 5/40 2320 /proc/meminfo: memFree=744028/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=0.01 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 622 2232 0 0 0 0 0 1 25 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.208094 s] /proc/loadavg: 1.06 1.03 0.76 5/40 2320 /proc/meminfo: memFree=744028/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=0.01 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 622 2232 0 0 0 0 0 1 25 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.308128 s] /proc/loadavg: 1.06 1.03 0.76 5/40 2320 /proc/meminfo: memFree=744028/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=0.01 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 622 2232 0 0 0 0 0 1 25 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.708232 s] /proc/loadavg: 1.06 1.03 0.76 5/40 2320 /proc/meminfo: memFree=744028/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=0.01 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 622 2232 0 0 0 0 0 1 25 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.50845 s] /proc/loadavg: 1.06 1.03 0.76 2/42 2332 /proc/meminfo: memFree=723160/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=0.01 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 622 2232 0 0 0 0 0 1 25 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=1924 CPUtime=0 /proc/2330/stat : 2330 (clasp) S 2318 2318 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 688430 1970176 159 1283457024 134512640 136285277 4287130224 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/2330/statm: 481 159 144 433 0 46 0 [pid=2331] ppid=2318 vsize=2584 CPUtime=0 /proc/2331/stat : 2331 (gringo) S 2318 2318 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 688430 2646016 272 1283457024 134512640 136933539 4288201712 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/2331/statm: 646 272 242 592 0 51 0 [pid=2332] ppid=2318 vsize=40448 CPUtime=1.49 /proc/2332/stat : 2332 (cudf2lp) R 2318 2318 1511 34817 1511 4202496 11650 0 0 0 144 5 0 0 25 0 1 0 688430 41418752 8739 1283457024 134512640 135786343 4294033824 18446744073709551615 134569396 0 0 6 0 0 0 0 17 0 0 0 0 /proc/2332/statm: 10112 8739 131 311 0 9799 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 47548 [startup+3.1089 s] /proc/loadavg: 1.06 1.03 0.76 3/42 2333 /proc/meminfo: memFree=688440/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=2.14 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 17930 0 0 0 0 202 12 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=21308 CPUtime=0.05 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 6041 0 0 0 4 1 0 0 18 0 1 0 688430 21819392 4844 1283457024 134512640 136285277 4287130224 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 5327 4844 177 433 0 4892 0 [pid=2331] ppid=2318 vsize=34204 CPUtime=0.9 /proc/2331/stat : 2331 (gringo) R 2318 2318 1511 34817 1511 4202496 10097 0 0 0 85 5 0 0 18 0 1 0 688430 35024896 6284 1283457024 134512640 136933539 4288201712 18446744073709551615 134688137 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2331/statm: 8551 6284 253 592 0 7956 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 58104 [startup+6.31031 s] /proc/loadavg: 1.06 1.03 0.76 2/40 2333 /proc/meminfo: memFree=691448/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=53108 CPUtime=2.36 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 16219 0 0 0 230 6 0 0 20 0 1 0 688430 54382592 13025 1283457024 134512640 136285277 4287130224 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 13277 13025 234 433 0 12842 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 55700 [startup+12.7026 s] /proc/loadavg: 1.05 1.03 0.76 2/40 2334 /proc/meminfo: memFree=692200/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=53108 CPUtime=8.75 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 16227 0 0 0 869 6 0 0 25 0 1 0 688430 54382592 13033 1283457024 134512640 136285277 4287130224 18446744073709551615 134669906 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 13277 13033 234 433 0 12842 0 Current children cumulated CPU time (s) 12.69 Current children cumulated vsize (KiB) 55700 [startup+25.5154 s] /proc/loadavg: 1.04 1.03 0.77 2/40 2335 /proc/meminfo: memFree=669632/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=77992 CPUtime=21.56 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 22426 0 0 0 2148 8 0 0 25 0 1 0 688430 79863808 19232 1283457024 134512640 136285277 4287130224 18446744073709551615 134733794 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 19498 19232 234 433 0 19063 0 Current children cumulated CPU time (s) 25.5 Current children cumulated vsize (KiB) 80584 [startup+51.1112 s] /proc/loadavg: 1.02 1.03 0.77 2/40 2337 /proc/meminfo: memFree=623256/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=122712 CPUtime=47.14 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 33581 0 0 0 4700 14 0 0 25 0 1 0 688430 125657088 30387 1283457024 134512640 136285277 4287130224 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 30678 30387 234 433 0 30243 0 Current children cumulated CPU time (s) 51.08 Current children cumulated vsize (KiB) 125304 [startup+102.305 s] /proc/loadavg: 1.01 1.02 0.78 2/39 2341 /proc/meminfo: memFree=562272/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=183532 CPUtime=98.27 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 48788 0 0 0 9807 20 0 0 25 0 1 0 688430 187936768 45594 1283457024 134512640 136285277 4287130224 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 45883 45594 234 433 0 45448 0 Current children cumulated CPU time (s) 102.21 Current children cumulated vsize (KiB) 186124 [startup+162.312 s] /proc/loadavg: 1.00 1.01 0.79 2/38 2344 /proc/meminfo: memFree=415712/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=330192 CPUtime=158.25 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 85386 0 0 0 15783 42 0 0 25 0 1 0 688430 338116608 82192 1283457024 134512640 136285277 4287130224 18446744073709551615 134623655 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 82548 82192 234 433 0 82113 0 Current children cumulated CPU time (s) 162.19 Current children cumulated vsize (KiB) 332784 [startup+222.311 s] /proc/loadavg: 1.00 1.01 0.81 2/38 2344 /proc/meminfo: memFree=316388/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=430092 CPUtime=218.23 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 110576 0 0 0 21767 56 0 0 25 0 1 0 688430 440414208 107141 1283457024 134512640 136285277 4287130224 18446744073709551615 134959967 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 107523 107141 234 433 0 107088 0 Current children cumulated CPU time (s) 222.17 Current children cumulated vsize (KiB) 432684 [startup+282.31 s] /proc/loadavg: 1.00 1.00 0.82 2/36 2348 /proc/meminfo: memFree=233480/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=514728 CPUtime=278.18 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 131641 0 0 0 27750 68 0 0 25 0 1 0 688430 527081472 128206 1283457024 134512640 136285277 4287130224 18446744073709551615 134623519 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 128682 128206 234 433 0 128247 0 Current children cumulated CPU time (s) 282.12 Current children cumulated vsize (KiB) 517320 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.212 s] /proc/loadavg: 1.00 1.00 0.82 2/36 2348 /proc/meminfo: memFree=233480/1048576 swapFree=0/0 [pid=2318] ppid=2317 vsize=2592 CPUtime=3.94 /proc/2318/stat : 2318 (aspcud-trendy-1) S 2317 2318 1511 34817 1511 4202496 623 36974 0 0 0 0 371 23 18 0 1 0 688428 2654208 298 1283457024 134512640 135304128 4293712112 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2318/statm: 648 298 251 194 0 35 0 [pid=2330] ppid=2318 vsize=514728 CPUtime=286.07 /proc/2330/stat : 2330 (clasp) R 2318 2318 1511 34817 1511 4202496 131643 0 0 0 28539 68 0 0 25 0 1 0 688430 527081472 128208 1283457024 134512640 136285277 4287130224 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/2330/statm: 128682 128208 234 433 0 128247 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 517320 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.262 CPU time (s): 290.07 CPU user time (s): 289.114 CPU system time (s): 0.956059 CPU usage (%): 99.9338 Max. virtual memory (cumulated for all children) (KiB): 517320 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.114 system time used= 0.956059 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 172943 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= 2675 involuntary context switches= 5602 runsolver used 0 second user time and 0 second system time The end