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/rand176.cudf.s-e-l-s-s.log.runsolver ./aspcud-paranoid-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand176.cudf /home/misc2010/tmp/201108251442/aspcud-paranoid-1.5/rand176.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: 0.98 0.28 0.10 5/37 5150 /proc/meminfo: memFree=313812/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2588 CPUtime=0 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 374 0 0 0 0 0 0 0 18 0 1 0 9946463 2650112 280 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/5147/statm: 647 280 234 194 0 34 0 [pid=5148] ppid=5147 vsize=2588 CPUtime=0 /proc/5148/stat : 5148 (aspcud-paranoid) S 5147 5147 4778 34817 4778 4202560 119 0 0 0 0 0 0 0 18 0 1 0 9946464 2650112 134 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/5148/statm: 647 134 87 194 0 34 0 [pid=5149] ppid=5148 vsize=2588 CPUtime=0 /proc/5149/stat : 5149 (aspcud-paranoid) R 5148 5147 4778 34817 4778 4202560 127 0 0 0 0 0 0 0 25 0 1 0 9946464 2650112 151 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/5149/statm: 647 151 104 194 0 34 0 [pid=5150] ppid=5149 vsize=2588 CPUtime=0 /proc/5150/stat : 5150 (aspcud-paranoid) R 5149 5147 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 9946464 2650112 47 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/5150/statm: 647 47 0 194 0 34 0 [startup+0.125132 s] /proc/loadavg: 0.98 0.28 0.10 5/37 5150 /proc/meminfo: memFree=313812/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=0.02 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 2935 0 0 0 0 0 2 25 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 2596 [startup+0.205148 s] /proc/loadavg: 0.98 0.28 0.10 5/37 5150 /proc/meminfo: memFree=313812/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=0.02 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 2935 0 0 0 0 0 2 25 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 2596 [startup+0.305144 s] /proc/loadavg: 0.98 0.28 0.10 5/37 5150 /proc/meminfo: memFree=313812/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=0.02 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 2935 0 0 0 0 0 2 25 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 2596 [startup+0.705173 s] /proc/loadavg: 0.98 0.28 0.10 5/37 5150 /proc/meminfo: memFree=313812/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=0.02 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 2935 0 0 0 0 0 2 25 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 2596 [startup+1.50523 s] /proc/loadavg: 0.98 0.28 0.10 2/38 5164 /proc/meminfo: memFree=277980/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=0.02 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 2935 0 0 0 0 0 2 25 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=1932 CPUtime=0 /proc/5162/stat : 5162 (clasp) S 5147 5147 4778 34817 4778 4202496 293 0 0 0 0 0 0 0 25 0 1 0 9946465 1978368 160 1283457024 134512640 136285277 4289295488 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/5162/statm: 483 160 144 433 0 48 0 [pid=5163] ppid=5147 vsize=2588 CPUtime=0 /proc/5163/stat : 5163 (gringo) S 5147 5147 4778 34817 4778 4202496 405 0 0 0 0 0 0 0 25 0 1 0 9946465 2650112 272 1283457024 134512640 136933539 4289141968 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5163/statm: 647 272 242 592 0 52 0 [pid=5164] ppid=5147 vsize=40664 CPUtime=1.34 /proc/5164/stat : 5164 (cudf2lp) R 5147 5147 4778 34817 4778 4202496 11621 0 0 0 132 2 0 0 25 0 1 0 9946465 41639936 8710 1283457024 134512640 135786343 4290233840 18446744073709551615 135199569 0 0 6 0 0 0 0 17 0 0 0 0 /proc/5164/statm: 10166 8710 126 311 0 9853 0 Current children cumulated CPU time (s) 1.36 Current children cumulated vsize (KiB) 47780 [startup+3.11057 s] /proc/loadavg: 0.98 0.30 0.10 3/38 5164 /proc/meminfo: memFree=239804/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=2.06 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 19140 0 0 0 0 200 6 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=18524 CPUtime=0.05 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 5093 0 0 0 4 1 0 0 18 0 1 0 9946465 18968576 4302 1283457024 134512640 136285277 4289295488 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 4631 4302 177 433 0 4196 0 [pid=5163] ppid=5147 vsize=29792 CPUtime=0.84 /proc/5163/stat : 5163 (gringo) R 5147 5147 4778 34817 4778 4202496 8587 0 0 0 83 1 0 0 18 0 1 0 9946465 30507008 6055 1283457024 134512640 136933539 4289141968 18446744073709551615 134814153 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5163/statm: 7448 6055 253 592 0 6853 0 Current children cumulated CPU time (s) 2.95 Current children cumulated vsize (KiB) 50912 [startup+6.31138 s] /proc/loadavg: 0.98 0.30 0.10 2/36 5164 /proc/meminfo: memFree=258568/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=35364 CPUtime=2.87 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 10518 0 0 0 283 4 0 0 22 0 1 0 9946465 36212736 8594 1283457024 134512640 136285277 4289295488 18446744073709551615 134649473 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 8841 8594 234 433 0 8406 0 Current children cumulated CPU time (s) 6.17 Current children cumulated vsize (KiB) 37960 [startup+12.7131 s] /proc/loadavg: 0.98 0.32 0.11 2/35 5164 /proc/meminfo: memFree=255600/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=38532 CPUtime=9.26 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 11325 0 0 0 922 4 0 0 25 0 1 0 9946465 39456768 9401 1283457024 134512640 136285277 4289295488 18446744073709551615 134955205 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 9633 9401 234 433 0 9198 0 Current children cumulated CPU time (s) 12.56 Current children cumulated vsize (KiB) 41128 [startup+25.5062 s] /proc/loadavg: 0.98 0.34 0.12 2/35 5164 /proc/meminfo: memFree=230304/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=63896 CPUtime=22.04 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 17670 0 0 0 2196 8 0 0 25 0 1 0 9946465 65429504 15746 1283457024 134512640 136285277 4289295488 18446744073709551615 134930666 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 15974 15746 234 433 0 15539 0 Current children cumulated CPU time (s) 25.34 Current children cumulated vsize (KiB) 66492 [startup+51.111 s] /proc/loadavg: 0.99 0.39 0.14 2/35 5164 /proc/meminfo: memFree=181076/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=113040 CPUtime=47.64 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 29939 0 0 0 4750 14 0 0 25 0 1 0 9946465 115752960 28015 1283457024 134512640 136285277 4289295488 18446744073709551615 134725838 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 28260 28015 234 433 0 27825 0 Current children cumulated CPU time (s) 50.94 Current children cumulated vsize (KiB) 115636 [startup+102.308 s] /proc/loadavg: 0.99 0.49 0.19 2/37 5167 /proc/meminfo: memFree=91896/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=202184 CPUtime=98.81 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 52241 0 0 0 9860 21 0 0 25 0 1 0 9946465 207036416 50212 1283457024 134512640 136285277 4289295488 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 50546 50212 234 433 0 50111 0 Current children cumulated CPU time (s) 102.11 Current children cumulated vsize (KiB) 204780 [startup+162.304 s] /proc/loadavg: 0.99 0.58 0.23 2/37 5173 /proc/meminfo: memFree=90904/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=202976 CPUtime=158.77 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 52456 0 0 0 15856 21 0 0 25 0 1 0 9946465 207847424 50427 1283457024 134512640 136285277 4289295488 18446744073709551615 134960080 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 50744 50427 234 433 0 50309 0 Current children cumulated CPU time (s) 162.07 Current children cumulated vsize (KiB) 205572 [startup+222.309 s] /proc/loadavg: 0.99 0.65 0.28 2/36 5175 /proc/meminfo: memFree=87944/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=206012 CPUtime=218.75 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 53218 0 0 0 21854 21 0 0 25 0 1 0 9946465 210956288 51189 1283457024 134512640 136285277 4289295488 18446744073709551615 134966958 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 51503 51189 234 433 0 51068 0 Current children cumulated CPU time (s) 222.05 Current children cumulated vsize (KiB) 208608 [startup+282.305 s] /proc/loadavg: 0.99 0.71 0.32 2/35 5175 /proc/meminfo: memFree=89068/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=204304 CPUtime=278.72 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 53220 0 0 0 27851 21 0 0 25 0 1 0 9946465 209207296 50776 1283457024 134512640 136285277 4289295488 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 51076 50776 234 433 0 50641 0 Current children cumulated CPU time (s) 282.02 Current children cumulated vsize (KiB) 206900 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.307 s] /proc/loadavg: 0.99 0.72 0.32 2/35 5175 /proc/meminfo: memFree=84604/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=209452 CPUtime=286.72 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 54487 0 0 0 28651 21 0 0 25 0 1 0 9946465 214478848 52043 1283457024 134512640 136285277 4289295488 18446744073709551615 134930933 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 52363 52043 234 433 0 51928 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 212048 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.307 s] /proc/loadavg: 0.99 0.72 0.32 2/35 5175 /proc/meminfo: memFree=84604/1048576 swapFree=0/0 [pid=5147] ppid=5146 vsize=2596 CPUtime=3.3 /proc/5147/stat : 5147 (aspcud-paranoid) S 5146 5147 4778 34817 4778 4202496 657 32369 0 0 0 0 320 10 18 0 1 0 9946463 2658304 299 1283457024 134512640 135304128 4291606240 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5147/statm: 649 299 251 194 0 36 0 [pid=5162] ppid=5147 vsize=209452 CPUtime=286.72 /proc/5162/stat : 5162 (clasp) R 5147 5147 4778 34817 4778 4202496 54487 0 0 0 28651 21 0 0 25 0 1 0 9946465 214478848 52043 1283457024 134512640 136285277 4289295488 18446744073709551615 134930933 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5162/statm: 52363 52043 234 433 0 51928 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 212048 Child status: 0 Real time (s): 290.347 CPU time (s): 290.07 CPU user time (s): 289.734 CPU system time (s): 0.336021 CPU usage (%): 99.9047 Max. virtual memory (cumulated for all children) (KiB): 212048 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.734 system time used= 0.336021 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 91214 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= 1398 involuntary context switches= 4545 runsolver used 0 second user time and 0 second system time The end