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/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/dudf-real//6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/6b0d1da0-c730-11df-a7c5-00163e3d3b7c.cudf.dudf-real.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.32 1.40 1.28 6/36 24313 /proc/meminfo: memFree=319644/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=0.01 /proc/24297/stat : 24297 (aspcud-paranoid) R 24296 24297 4778 34817 4778 4202496 628 2934 0 0 0 1 0 0 25 0 1 0 11185287 2662400 298 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0 /proc/24297/statm: 650 298 250 194 0 37 0 [pid=24311] ppid=24297 vsize=2600 CPUtime=0 /proc/24311/stat : 24311 (aspcud-paranoid) R 24297 24297 4778 34817 4778 4202560 111 0 0 0 0 0 0 0 25 0 1 0 11185288 2662400 132 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0 /proc/24311/statm: 650 132 83 194 0 37 0 [pid=24312] ppid=24297 vsize=2600 CPUtime=0 /proc/24312/stat : 24312 (aspcud-paranoid) S 24297 24297 4778 34817 4778 4202560 111 0 0 0 0 0 0 0 25 0 1 0 11185288 2662400 132 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564457842 0 0 17 0 0 0 0 /proc/24312/statm: 650 132 83 194 0 37 0 [pid=24313] ppid=24297 vsize=2600 CPUtime=0 /proc/24313/stat : 24313 (aspcud-paranoid) R 24297 24297 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 11185288 2662400 48 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0 /proc/24313/statm: 650 48 0 194 0 37 0 [startup+0.180933 s] /proc/loadavg: 1.32 1.40 1.28 6/36 24313 /proc/meminfo: memFree=319644/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=0.01 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 2934 0 0 0 1 0 0 25 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=1932 CPUtime=0 /proc/24311/stat : 24311 (clasp) S 24297 24297 4778 34817 4778 4202496 293 0 0 0 0 0 0 0 25 0 1 0 11185288 1978368 160 1283457024 134512640 136285277 4292650928 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24311/statm: 483 160 144 433 0 48 0 [pid=24312] ppid=24297 vsize=2588 CPUtime=0 /proc/24312/stat : 24312 (gringo) S 24297 24297 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11185288 2650112 272 1283457024 134512640 136933539 4287171312 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24312/statm: 647 272 242 592 0 52 0 [pid=24313] ppid=24297 vsize=5352 CPUtime=0.14 /proc/24313/stat : 24313 (cudf2lp) R 24297 24297 4778 34817 4778 4202496 1333 0 0 0 14 0 0 0 25 0 1 0 11185288 5480448 1066 1283457024 134512640 135786343 4289193200 18446744073709551615 134924815 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24313/statm: 1338 1066 125 311 0 1025 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 12472 [startup+0.210033 s] /proc/loadavg: 1.32 1.40 1.28 6/36 24313 /proc/meminfo: memFree=319644/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=0.01 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 2934 0 0 0 1 0 0 25 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=1932 CPUtime=0 /proc/24311/stat : 24311 (clasp) S 24297 24297 4778 34817 4778 4202496 293 0 0 0 0 0 0 0 25 0 1 0 11185288 1978368 160 1283457024 134512640 136285277 4292650928 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24311/statm: 483 160 144 433 0 48 0 [pid=24312] ppid=24297 vsize=2588 CPUtime=0 /proc/24312/stat : 24312 (gringo) S 24297 24297 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11185288 2650112 272 1283457024 134512640 136933539 4287171312 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24312/statm: 647 272 242 592 0 52 0 [pid=24313] ppid=24297 vsize=5844 CPUtime=0.16 /proc/24313/stat : 24313 (cudf2lp) D 24297 24297 4778 34817 4778 4202496 1461 0 0 0 16 0 0 0 25 0 1 0 11185288 5984256 1194 1283457024 134512640 135786343 4289193200 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0 /proc/24313/statm: 1461 1194 125 311 0 1148 0 Current children cumulated CPU time (s) 0.17 Current children cumulated vsize (KiB) 12964 [startup+0.304935 s] /proc/loadavg: 1.32 1.40 1.28 6/36 24313 /proc/meminfo: memFree=319644/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=0.01 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 2934 0 0 0 1 0 0 25 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=1932 CPUtime=0 /proc/24311/stat : 24311 (clasp) S 24297 24297 4778 34817 4778 4202496 293 0 0 0 0 0 0 0 25 0 1 0 11185288 1978368 160 1283457024 134512640 136285277 4292650928 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24311/statm: 483 160 144 433 0 48 0 [pid=24312] ppid=24297 vsize=2588 CPUtime=0 /proc/24312/stat : 24312 (gringo) S 24297 24297 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11185288 2650112 272 1283457024 134512640 136933539 4287171312 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24312/statm: 647 272 242 592 0 52 0 [pid=24313] ppid=24297 vsize=8528 CPUtime=0.25 /proc/24313/stat : 24313 (cudf2lp) R 24297 24297 4778 34817 4778 4202496 2230 0 0 0 25 0 0 0 25 0 1 0 11185288 8732672 1786 1283457024 134512640 135786343 4289193200 18446744073709551615 134566956 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24313/statm: 2132 1786 125 311 0 1819 0 Current children cumulated CPU time (s) 0.26 Current children cumulated vsize (KiB) 15648 [startup+0.704959 s] /proc/loadavg: 1.32 1.40 1.28 6/36 24313 /proc/meminfo: memFree=319644/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=0.01 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 2934 0 0 0 1 0 0 25 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=1932 CPUtime=0 /proc/24311/stat : 24311 (clasp) S 24297 24297 4778 34817 4778 4202496 293 0 0 0 0 0 0 0 25 0 1 0 11185288 1978368 160 1283457024 134512640 136285277 4292650928 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24311/statm: 483 160 144 433 0 48 0 [pid=24312] ppid=24297 vsize=2588 CPUtime=0 /proc/24312/stat : 24312 (gringo) S 24297 24297 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11185288 2650112 272 1283457024 134512640 136933539 4287171312 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24312/statm: 647 272 242 592 0 52 0 [pid=24313] ppid=24297 vsize=14540 CPUtime=0.43 /proc/24313/stat : 24313 (cudf2lp) R 24297 24297 4778 34817 4778 4202496 3946 0 0 0 42 1 0 0 25 0 1 0 11185288 14888960 3100 1283457024 134512640 135786343 4289193200 18446744073709551615 134849983 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24313/statm: 3635 3100 126 311 0 3322 0 Current children cumulated CPU time (s) 0.44 Current children cumulated vsize (KiB) 21660 [startup+1.50504 s] /proc/loadavg: 1.32 1.40 1.28 2/37 24314 /proc/meminfo: memFree=289848/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=0.01 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 2934 0 0 0 1 0 0 25 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=1932 CPUtime=0 /proc/24311/stat : 24311 (clasp) S 24297 24297 4778 34817 4778 4202496 293 0 0 0 0 0 0 0 25 0 1 0 11185288 1978368 160 1283457024 134512640 136285277 4292650928 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24311/statm: 483 160 144 433 0 48 0 [pid=24312] ppid=24297 vsize=2588 CPUtime=0 /proc/24312/stat : 24312 (gringo) S 24297 24297 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 11185288 2650112 272 1283457024 134512640 136933539 4287171312 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24312/statm: 647 272 242 592 0 52 0 [pid=24313] ppid=24297 vsize=25924 CPUtime=0.98 /proc/24313/stat : 24313 (cudf2lp) R 24297 24297 4778 34817 4778 4202496 7433 0 0 0 94 4 0 0 25 0 1 0 11185288 26546176 5688 1283457024 134512640 135786343 4289193200 18446744073709551615 134633194 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24313/statm: 6481 5688 126 311 0 6168 0 Current children cumulated CPU time (s) 0.99 Current children cumulated vsize (KiB) 33044 [startup+3.10681 s] /proc/loadavg: 1.32 1.40 1.28 3/37 24314 /proc/meminfo: memFree=259692/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=1.91 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 15163 0 0 0 1 185 5 18 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=14944 CPUtime=0.02 /proc/24311/stat : 24311 (clasp) R 24297 24297 4778 34817 4778 4202496 4119 0 0 0 2 0 0 0 18 0 1 0 11185288 15302656 3328 1283457024 134512640 136285277 4292650928 18446744073709551615 135648438 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24311/statm: 3736 3328 177 433 0 3301 0 [pid=24312] ppid=24297 vsize=23916 CPUtime=0.62 /proc/24312/stat : 24312 (gringo) R 24297 24297 4778 34817 4778 4202496 6705 0 0 0 59 3 0 0 18 0 1 0 11185288 24489984 4737 1283457024 134512640 136933539 4287171312 18446744073709551615 134889835 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24312/statm: 5979 4737 253 592 0 5384 0 Current children cumulated CPU time (s) 2.55 Current children cumulated vsize (KiB) 41460 Solver just ended. Dumping a history of the last processes samples [startup+3.20683 s] /proc/loadavg: 1.32 1.40 1.28 3/37 24314 /proc/meminfo: memFree=259692/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=1.91 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 15163 0 0 0 1 185 5 18 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=17056 CPUtime=0.04 /proc/24311/stat : 24311 (clasp) R 24297 24297 4778 34817 4778 4202496 4694 0 0 0 4 0 0 0 18 0 1 0 11185288 17465344 3903 1283457024 134512640 136285277 4292650928 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24311/statm: 4264 3903 177 433 0 3829 0 [pid=24312] ppid=24297 vsize=27344 CPUtime=0.71 /proc/24312/stat : 24312 (gringo) R 24297 24297 4778 34817 4778 4202496 7706 0 0 0 68 3 0 0 18 0 1 0 11185288 28000256 5609 1283457024 134512640 136933539 4287171312 18446744073709551615 134729759 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/24312/statm: 6836 5609 253 592 0 6241 0 Current children cumulated CPU time (s) 2.66 Current children cumulated vsize (KiB) 47000 [startup+4.00702 s] /proc/loadavg: 1.32 1.40 1.28 3/36 24314 /proc/meminfo: memFree=255368/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=3.13 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 26892 0 0 0 1 302 10 18 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=36108 CPUtime=0.32 /proc/24311/stat : 24311 (clasp) R 24297 24297 4778 34817 4778 4202496 10447 0 0 0 31 1 0 0 18 0 1 0 11185288 36974592 8716 1283457024 134512640 136285277 4292650928 18446744073709551615 135631709 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24311/statm: 9027 8716 208 433 0 8592 0 Current children cumulated CPU time (s) 3.45 Current children cumulated vsize (KiB) 38708 [startup+4.80716 s] /proc/loadavg: 1.30 1.39 1.28 2/35 24314 /proc/meminfo: memFree=263816/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=3.13 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 26892 0 0 0 1 302 10 18 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=35564 CPUtime=1.12 /proc/24311/stat : 24311 (clasp) R 24297 24297 4778 34817 4778 4202496 10495 0 0 0 111 1 0 0 19 0 1 0 11185288 36417536 8638 1283457024 134512640 136285277 4292650928 18446744073709551615 134893019 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24311/statm: 8891 8638 234 433 0 8456 0 Current children cumulated CPU time (s) 4.25 Current children cumulated vsize (KiB) 38164 [startup+5.00722 s] /proc/loadavg: 1.30 1.39 1.28 2/35 24314 /proc/meminfo: memFree=263816/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2600 CPUtime=3.13 /proc/24297/stat : 24297 (aspcud-paranoid) S 24296 24297 4778 34817 4778 4202496 654 26892 0 0 0 1 302 10 18 0 1 0 11185287 2662400 299 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24297/statm: 650 299 251 194 0 37 0 [pid=24311] ppid=24297 vsize=35564 CPUtime=1.32 /proc/24311/stat : 24311 (clasp) R 24297 24297 4778 34817 4778 4202496 10496 0 0 0 131 1 0 0 19 0 1 0 11185288 36417536 8639 1283457024 134512640 136285277 4292650928 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24311/statm: 8891 8639 234 433 0 8456 0 Current children cumulated CPU time (s) 4.45 Current children cumulated vsize (KiB) 38164 [startup+5.10722 s] /proc/loadavg: 1.30 1.39 1.28 2/35 24314 /proc/meminfo: memFree=263816/1048576 swapFree=0/0 [pid=24297] ppid=24296 vsize=2732 CPUtime=4.55 /proc/24297/stat : 24297 (aspcud-paranoid) R 24296 24297 4778 34817 4778 4202496 885 39210 0 0 0 2 441 12 18 0 1 0 11185287 2797568 335 1283457024 134512640 135304128 4287628016 18446744073709551615 4294960130 0 0 16902 1132543225 0 0 0 17 0 0 0 0 /proc/24297/statm: 683 335 256 194 0 70 0 Current children cumulated CPU time (s) 4.55 Current children cumulated vsize (KiB) 2732 Child status: 0 Real time (s): 5.12637 CPU time (s): 4.57629 CPU user time (s): 4.41628 CPU system time (s): 0.16001 CPU usage (%): 89.2695 Max. virtual memory (cumulated for all children) (KiB): 72148 getrusage(RUSAGE_CHILDREN,...) data: user time used= 4.41628 system time used= 0.16001 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 41976 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= 1388 involuntary context switches= 1068 runsolver used 0 second user time and 0 second system time The end