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/rand946.cudf.s-e-l-s-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand946.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand946.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.14 1.09 1.03 5/36 16984 /proc/meminfo: memFree=444324/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2588 CPUtime=0 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 3805689 2650112 279 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/16981/statm: 647 279 234 194 0 34 0 [pid=16982] ppid=16981 vsize=2588 CPUtime=0 /proc/16982/stat : 16982 (aspcud-trendy-1) S 16981 16981 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 3805689 2650112 133 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/16982/statm: 647 133 87 194 0 34 0 [pid=16983] ppid=16982 vsize=2588 CPUtime=0 /proc/16983/stat : 16983 (aspcud-trendy-1) R 16982 16981 1511 34817 1511 4202560 126 0 0 0 0 0 0 0 25 0 1 0 3805689 2650112 150 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/16983/statm: 647 150 104 194 0 34 0 [pid=16984] ppid=16983 vsize=2588 CPUtime=0 /proc/16984/stat : 16984 (aspcud-trendy-1) R 16983 16981 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3805689 2650112 46 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/16984/statm: 647 46 0 194 0 34 0 [startup+0.165194 s] /proc/loadavg: 1.14 1.09 1.03 5/36 16984 /proc/meminfo: memFree=444324/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=0 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.205182 s] /proc/loadavg: 1.14 1.09 1.03 5/36 16984 /proc/meminfo: memFree=444324/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=0 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.305195 s] /proc/loadavg: 1.14 1.09 1.03 5/36 16984 /proc/meminfo: memFree=444324/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=0 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.705316 s] /proc/loadavg: 1.14 1.09 1.03 5/36 16984 /proc/meminfo: memFree=444324/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=0 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50545 s] /proc/loadavg: 1.13 1.09 1.03 2/37 16995 /proc/meminfo: memFree=423720/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=0 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=1928 CPUtime=0 /proc/16993/stat : 16993 (clasp) S 16981 16981 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 3805691 1974272 159 1283457024 134512640 136285277 4291595952 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/16993/statm: 482 159 144 433 0 47 0 [pid=16994] ppid=16981 vsize=2584 CPUtime=0 /proc/16994/stat : 16994 (gringo) S 16981 16981 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 3805691 2646016 272 1283457024 134512640 136933539 4291608368 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16994/statm: 646 272 242 592 0 51 0 [pid=16995] ppid=16981 vsize=40660 CPUtime=1.49 /proc/16995/stat : 16995 (cudf2lp) R 16981 16981 1511 34817 1511 4202496 11696 0 0 0 145 4 0 0 25 0 1 0 3805691 41635840 8785 1283457024 134512640 135786343 4288207888 18446744073709551615 134566286 0 0 6 0 0 0 0 17 0 0 0 0 /proc/16995/statm: 10165 8785 126 311 0 9852 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 47768 [startup+3.10611 s] /proc/loadavg: 1.13 1.09 1.03 3/37 16995 /proc/meminfo: memFree=389496/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=0 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 622 2230 0 0 0 0 0 0 25 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=17316 CPUtime=0.09 /proc/16993/stat : 16993 (clasp) S 16981 16981 1511 34817 1511 4202496 4795 0 0 0 8 1 0 0 18 0 1 0 3805691 17731584 4004 1283457024 134512640 136285277 4291595952 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/16993/statm: 4329 4004 177 433 0 3894 0 [pid=16994] ppid=16981 vsize=22088 CPUtime=0.72 /proc/16994/stat : 16994 (gringo) S 16981 16981 1511 34817 1511 4202496 6891 0 0 0 71 1 0 0 18 0 1 0 3805691 22618112 4618 1283457024 134512640 136933539 4291608368 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16994/statm: 5522 4618 242 592 0 4927 0 [pid=16995] ppid=16981 vsize=17676 CPUtime=2.26 /proc/16995/stat : 16995 (cudf2lp) R 16981 16981 1511 34817 1511 4202496 16201 0 0 0 220 6 0 0 25 0 1 0 3805691 18100224 4242 1283457024 134512640 135786343 4288207888 18446744073709551615 135191367 0 0 6 0 0 0 0 17 0 0 0 0 /proc/16995/statm: 4419 4242 138 311 0 4106 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 59676 [startup+6.30749 s] /proc/loadavg: 1.12 1.09 1.02 2/35 16995 /proc/meminfo: memFree=389164/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=55604 CPUtime=2.21 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 17263 0 0 0 209 12 0 0 20 0 1 0 3805691 56938496 13654 1283457024 134512640 136285277 4291595952 18446744073709551615 134669486 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 13901 13654 234 433 0 13466 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 58200 [startup+12.7101 s] /proc/loadavg: 1.11 1.09 1.02 2/35 16995 /proc/meminfo: memFree=390032/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=55604 CPUtime=8.6 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 17284 0 0 0 848 12 0 0 25 0 1 0 3805691 56938496 13675 1283457024 134512640 136285277 4291595952 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 13901 13675 234 433 0 13466 0 Current children cumulated CPU time (s) 12.69 Current children cumulated vsize (KiB) 58200 [startup+25.5031 s] /proc/loadavg: 1.09 1.08 1.02 2/35 16995 /proc/meminfo: memFree=371804/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=75412 CPUtime=21.39 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 22212 0 0 0 2126 13 0 0 25 0 1 0 3805691 77221888 18603 1283457024 134512640 136285277 4291595952 18446744073709551615 134623655 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 18853 18603 234 433 0 18418 0 Current children cumulated CPU time (s) 25.48 Current children cumulated vsize (KiB) 78008 [startup+51.109 s] /proc/loadavg: 1.05 1.07 1.02 2/35 16995 /proc/meminfo: memFree=320344/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=125788 CPUtime=46.99 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 34812 0 0 0 4679 20 0 0 25 0 1 0 3805691 128806912 31203 1283457024 134512640 136285277 4291595952 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 31447 31203 234 433 0 31012 0 Current children cumulated CPU time (s) 51.08 Current children cumulated vsize (KiB) 128384 [startup+102.311 s] /proc/loadavg: 1.02 1.06 1.02 2/35 16995 /proc/meminfo: memFree=260452/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=185664 CPUtime=98.15 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 49746 0 0 0 9785 30 0 0 25 0 1 0 3805691 190119936 46137 1283457024 134512640 136285277 4291595952 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 46416 46137 234 433 0 45981 0 Current children cumulated CPU time (s) 102.24 Current children cumulated vsize (KiB) 188260 [startup+162.309 s] /proc/loadavg: 1.01 1.05 1.01 2/37 17002 /proc/meminfo: memFree=244184/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=201004 CPUtime=158.1 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 54467 0 0 0 15777 33 0 0 25 0 1 0 3805691 205828096 50012 1283457024 134512640 136285277 4291595952 18446744073709551615 134966952 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 50251 50012 234 433 0 49816 0 Current children cumulated CPU time (s) 162.19 Current children cumulated vsize (KiB) 203600 [startup+222.305 s] /proc/loadavg: 1.00 1.04 1.00 2/36 17006 /proc/meminfo: memFree=185300/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=260752 CPUtime=218.06 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 69387 0 0 0 21769 37 0 0 25 0 1 0 3805691 267010048 64932 1283457024 134512640 136285277 4291595952 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 65188 64932 234 433 0 64753 0 Current children cumulated CPU time (s) 222.15 Current children cumulated vsize (KiB) 263348 [startup+282.312 s] /proc/loadavg: 1.00 1.03 1.00 2/35 17006 /proc/meminfo: memFree=136204/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=309460 CPUtime=278.02 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 81561 0 0 0 27757 45 0 0 25 0 1 0 3805691 316887040 77106 1283457024 134512640 136285277 4291595952 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 77365 77106 234 433 0 76930 0 Current children cumulated CPU time (s) 282.11 Current children cumulated vsize (KiB) 312056 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.204 s] /proc/loadavg: 1.00 1.03 1.00 2/35 17006 /proc/meminfo: memFree=136204/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=309460 CPUtime=285.91 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 81561 0 0 0 28546 45 0 0 25 0 1 0 3805691 316887040 77106 1283457024 134512640 136285277 4291595952 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 77365 77106 234 433 0 76930 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 312056 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.204 s] /proc/loadavg: 1.00 1.03 1.00 2/35 17006 /proc/meminfo: memFree=136204/1048576 swapFree=0/0 [pid=16981] ppid=16980 vsize=2596 CPUtime=4.09 /proc/16981/stat : 16981 (aspcud-trendy-1) S 16980 16981 1511 34817 1511 4202496 623 38029 0 0 0 0 395 14 18 0 1 0 3805689 2658304 298 1283457024 134512640 135304128 4293376160 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16981/statm: 649 298 251 194 0 36 0 [pid=16993] ppid=16981 vsize=309460 CPUtime=285.91 /proc/16993/stat : 16993 (clasp) R 16981 16981 1511 34817 1511 4202496 81561 0 0 0 28546 45 0 0 25 0 1 0 3805691 316887040 77106 1283457024 134512640 136285277 4291595952 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/16993/statm: 77365 77106 234 433 0 76930 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 312056 Child status: 0 Real time (s): 290.247 CPU time (s): 290.058 CPU user time (s): 289.446 CPU system time (s): 0.612038 CPU usage (%): 99.9348 Max. virtual memory (cumulated for all children) (KiB): 312056 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.446 system time used= 0.612038 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 123963 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= 2899 involuntary context switches= 5764 runsolver used 0 second user time and 0 second system time The end