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/rand477.cudf.s-e-l-s.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l-s/rand477.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand477.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.07 1.04 1.04 6/35 15438 /proc/meminfo: memFree=390956/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2584 CPUtime=0 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 372 0 0 0 0 0 0 0 18 0 1 0 10821486 2646016 279 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/15436/statm: 646 279 234 194 0 33 0 [pid=15437] ppid=15436 vsize=2584 CPUtime=0 /proc/15437/stat : 15437 (aspcud-paranoid) R 15436 15436 4778 34817 4778 4202560 110 0 0 0 0 0 0 0 25 0 1 0 10821486 2646016 132 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15437/statm: 646 132 86 194 0 33 0 [pid=15438] ppid=15437 vsize=2584 CPUtime=0 /proc/15438/stat : 15438 (aspcud-paranoid) R 15437 15436 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10821486 2646016 46 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/15438/statm: 646 46 0 194 0 33 0 [startup+0.111112 s] /proc/loadavg: 1.07 1.04 1.04 6/35 15438 /proc/meminfo: memFree=390956/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=0.01 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 2939 0 0 0 0 0 1 25 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.207118 s] /proc/loadavg: 1.07 1.04 1.04 6/35 15438 /proc/meminfo: memFree=390956/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=0.01 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 2939 0 0 0 0 0 1 25 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.307114 s] /proc/loadavg: 1.07 1.04 1.04 6/35 15438 /proc/meminfo: memFree=390956/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=0.01 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 2939 0 0 0 0 0 1 25 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.707141 s] /proc/loadavg: 1.07 1.04 1.04 6/35 15438 /proc/meminfo: memFree=390956/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=0.01 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 2939 0 0 0 0 0 1 25 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.50719 s] /proc/loadavg: 1.07 1.04 1.04 2/37 15453 /proc/meminfo: memFree=355228/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=0.01 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 2939 0 0 0 0 0 1 25 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=1928 CPUtime=0 /proc/15451/stat : 15451 (clasp) S 15436 15436 4778 34817 4778 4202496 292 0 0 0 0 0 0 0 25 0 1 0 10821488 1974272 160 1283457024 134512640 136285277 4289492144 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/15451/statm: 482 160 144 433 0 47 0 [pid=15452] ppid=15436 vsize=2584 CPUtime=0 /proc/15452/stat : 15452 (gringo) S 15436 15436 4778 34817 4778 4202496 404 0 0 0 0 0 0 0 25 0 1 0 10821488 2646016 272 1283457024 134512640 136933539 4293599504 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/15452/statm: 646 272 242 592 0 51 0 [pid=15453] ppid=15436 vsize=40448 CPUtime=1.3 /proc/15453/stat : 15453 (cudf2lp) R 15436 15436 4778 34817 4778 4202496 11590 0 0 0 128 2 0 0 25 0 1 0 10821488 41418752 8680 1283457024 134512640 135786343 4287523680 18446744073709551615 135220079 0 0 6 0 0 0 0 17 0 0 0 0 /proc/15453/statm: 10112 8680 126 311 0 9799 0 Current children cumulated CPU time (s) 1.31 Current children cumulated vsize (KiB) 47552 [startup+3.1061 s] /proc/loadavg: 1.07 1.04 1.04 4/37 15453 /proc/meminfo: memFree=316524/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=1.93 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 18635 0 0 0 0 189 4 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=21960 CPUtime=0.07 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 6078 0 0 0 6 1 0 0 18 0 1 0 10821488 22487040 5085 1283457024 134512640 136285277 4289492144 18446744073709551615 134835902 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 5490 5085 177 433 0 5055 0 [pid=15452] ppid=15436 vsize=35452 CPUtime=0.9 /proc/15452/stat : 15452 (gringo) R 15436 15436 4778 34817 4778 4202496 10136 0 0 0 87 3 0 0 18 0 1 0 10821488 36302848 7219 1283457024 134512640 136933539 4293599504 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/15452/statm: 8863 7219 253 592 0 8268 0 Current children cumulated CPU time (s) 2.9 Current children cumulated vsize (KiB) 60004 [startup+6.30701 s] /proc/loadavg: 1.07 1.04 1.04 2/35 15453 /proc/meminfo: memFree=337520/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=34260 CPUtime=2.98 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 10220 0 0 0 296 2 0 0 24 0 1 0 10821488 35082240 8319 1283457024 134512640 136285277 4289492144 18446744073709551615 134931346 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 8565 8319 234 433 0 8130 0 Current children cumulated CPU time (s) 6.1 Current children cumulated vsize (KiB) 36852 [startup+12.7083 s] /proc/loadavg: 1.06 1.04 1.04 2/35 15453 /proc/meminfo: memFree=322516/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=49808 CPUtime=9.38 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 14123 0 0 0 934 4 0 0 25 0 1 0 10821488 51003392 12222 1283457024 134512640 136285277 4289492144 18446744073709551615 134959571 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 12452 12222 234 433 0 12017 0 Current children cumulated CPU time (s) 12.5 Current children cumulated vsize (KiB) 52400 [startup+25.5117 s] /proc/loadavg: 1.05 1.04 1.04 2/35 15453 /proc/meminfo: memFree=301312/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=70912 CPUtime=22.17 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 19376 0 0 0 2208 9 0 0 25 0 1 0 10821488 72613888 17475 1283457024 134512640 136285277 4289492144 18446744073709551615 134931382 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 17728 17475 234 433 0 17293 0 Current children cumulated CPU time (s) 25.29 Current children cumulated vsize (KiB) 73504 [startup+51.107 s] /proc/loadavg: 1.03 1.03 1.04 2/35 15453 /proc/meminfo: memFree=249976/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=122280 CPUtime=47.73 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 32212 0 0 0 4755 18 0 0 25 0 1 0 10821488 125214720 30311 1283457024 134512640 136285277 4289492144 18446744073709551615 134650344 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 30570 30311 234 433 0 30135 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 124872 [startup+102.31 s] /proc/loadavg: 1.01 1.03 1.03 2/35 15453 /proc/meminfo: memFree=186736/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=185492 CPUtime=98.87 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 48060 0 0 0 9863 24 0 0 25 0 1 0 10821488 189943808 46054 1283457024 134512640 136285277 4289492144 18446744073709551615 134931380 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 46373 46054 234 433 0 45938 0 Current children cumulated CPU time (s) 101.99 Current children cumulated vsize (KiB) 188084 [startup+162.306 s] /proc/loadavg: 1.00 1.02 1.03 2/35 15453 /proc/meminfo: memFree=183016/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=189188 CPUtime=158.82 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 48980 0 0 0 15857 25 0 0 25 0 1 0 10821488 193728512 46974 1283457024 134512640 136285277 4289492144 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 47297 46974 234 433 0 46862 0 Current children cumulated CPU time (s) 161.94 Current children cumulated vsize (KiB) 191780 [startup+222.31 s] /proc/loadavg: 1.00 1.01 1.02 2/37 15461 /proc/meminfo: memFree=182868/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=189188 CPUtime=218.78 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 48984 0 0 0 21852 26 0 0 25 0 1 0 10821488 193728512 46978 1283457024 134512640 136285277 4289492144 18446744073709551615 134966979 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 47297 46978 234 433 0 46862 0 Current children cumulated CPU time (s) 221.9 Current children cumulated vsize (KiB) 191780 [startup+282.314 s] /proc/loadavg: 1.00 1.01 1.02 2/36 15464 /proc/meminfo: memFree=181396/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=190640 CPUtime=278.75 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 49359 0 0 0 27848 27 0 0 25 0 1 0 10821488 195215360 47353 1283457024 134512640 136285277 4289492144 18446744073709551615 134930652 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 47660 47353 234 433 0 47225 0 Current children cumulated CPU time (s) 281.87 Current children cumulated vsize (KiB) 193232 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.506 s] /proc/loadavg: 1.00 1.01 1.02 2/36 15464 /proc/meminfo: memFree=181396/1048576 swapFree=0/0 [pid=15436] ppid=15435 vsize=2592 CPUtime=3.12 /proc/15436/stat : 15436 (aspcud-paranoid) S 15435 15436 4778 34817 4778 4202496 648 31701 0 0 0 0 300 12 18 0 1 0 10821486 2654208 298 1283457024 134512640 135304128 4291231376 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/15436/statm: 648 298 251 194 0 35 0 [pid=15451] ppid=15436 vsize=190640 CPUtime=286.93 /proc/15451/stat : 15451 (clasp) R 15436 15436 4778 34817 4778 4202496 49359 0 0 0 28666 27 0 0 25 0 1 0 10821488 195215360 47353 1283457024 134512640 136285277 4289492144 18446744073709551615 134686311 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/15451/statm: 47660 47353 234 433 0 47225 0 Current children cumulated CPU time (s) 290.05 Current children cumulated vsize (KiB) 193232 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.548 CPU time (s): 290.11 CPU user time (s): 289.686 CPU system time (s): 0.424026 CPU usage (%): 99.8495 Max. virtual memory (cumulated for all children) (KiB): 193232 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.686 system time used= 0.424026 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 85401 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= 1344 involuntary context switches= 4482 runsolver used 0.008 second user time and 0 second system time The end