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/201108311143/aspcud-1.5/rand18.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand18.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand18.cudf.user-upgrades.result -sum(installedsize) 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.00 1.00 1.00 3/39 21820 /proc/meminfo: memFree=630300/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2588 CPUtime=0 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 25 0 1 0 61737078 2650112 280 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/21817/statm: 647 280 234 194 0 34 0 [pid=21818] ppid=21817 vsize=2588 CPUtime=0 /proc/21818/stat : 21818 (aspcud-1.5) S 21817 21817 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 25 0 1 0 61737078 2650112 134 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/21818/statm: 647 134 87 194 0 34 0 [pid=21819] ppid=21818 vsize=2588 CPUtime=0 /proc/21819/stat : 21819 (aspcud-1.5) S 21818 21817 19908 34817 19908 4202560 157 0 0 0 0 0 0 0 25 0 1 0 61737078 2650112 163 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 0 65538 18446744071564329979 0 0 17 0 0 0 0 /proc/21819/statm: 647 163 116 194 0 34 0 [pid=21820] ppid=21819 vsize=168 CPUtime=0.01 /proc/21820/stat : 21820 (readlink) R 21819 21817 19908 34817 19908 4194304 57 0 0 0 0 1 0 0 25 0 1 0 61737078 172032 4 1283457024 134512640 134543716 4291276336 18446744073709551615 4159899728 0 0 0 0 0 0 0 17 0 0 0 0 /proc/21820/statm: 42 4 0 8 0 4 0 [startup+0.182995 s] /proc/loadavg: 1.00 1.00 1.00 3/39 21820 /proc/meminfo: memFree=630300/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=0.01 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 1523 0 0 0 0 0 1 25 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.215563 s] /proc/loadavg: 1.00 1.00 1.00 3/39 21820 /proc/meminfo: memFree=630300/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=0.01 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 1523 0 0 0 0 0 1 25 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.307 s] /proc/loadavg: 1.00 1.00 1.00 3/39 21820 /proc/meminfo: memFree=630300/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=0.01 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 1523 0 0 0 0 0 1 25 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.707018 s] /proc/loadavg: 1.00 1.00 1.00 3/39 21820 /proc/meminfo: memFree=630300/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=0.01 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 1523 0 0 0 0 0 1 25 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50708 s] /proc/loadavg: 1.00 1.00 1.00 2/40 21828 /proc/meminfo: memFree=597888/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=0.01 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 1523 0 0 0 0 0 1 25 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=1924 CPUtime=0 /proc/21826/stat : 21826 (clasp) S 21817 21817 19908 34817 19908 4202496 291 0 0 0 0 0 0 0 25 0 1 0 61737079 1970176 159 1283457024 134512640 136285277 4294390128 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/21826/statm: 481 159 144 433 0 46 0 [pid=21827] ppid=21817 vsize=2584 CPUtime=0 /proc/21827/stat : 21827 (gringo) S 21817 21817 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 61737079 2646016 272 1283457024 134512640 136933539 4286655104 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/21827/statm: 646 272 242 592 0 51 0 [pid=21828] ppid=21817 vsize=28116 CPUtime=1.31 /proc/21828/stat : 21828 (cudf2lp) R 21817 21817 19908 34817 19908 4202496 8019 0 0 0 127 4 0 0 25 0 1 0 61737079 28790784 6275 1283457024 134512640 135786343 4293507360 18446744073709551615 134566170 0 0 6 0 0 0 0 17 0 0 0 0 /proc/21828/statm: 7029 6275 128 311 0 6716 0 Current children cumulated CPU time (s) 1.32 Current children cumulated vsize (KiB) 35220 [startup+3.11098 s] /proc/loadavg: 1.00 1.00 1.00 1/40 21828 /proc/meminfo: memFree=577856/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.29 /proc/21817/stat : 21817 (aspcud-1.5) R 21816 21817 19908 34817 19908 4202496 576 15498 0 0 0 0 221 8 19 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=4688 CPUtime=0.04 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 1067 0 0 0 3 1 0 0 18 0 1 0 61737079 4800512 930 1283457024 134512640 136285277 4294390128 18446744073709551615 134737696 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 1172 930 212 433 0 737 0 [pid=21827] ppid=21817 vsize=0 CPUtime=0.05 /proc/21827/stat : 21827 (gringo) Z 21817 21817 19908 34817 19908 4202508 1333 0 0 0 5 0 0 0 18 0 1 0 61737079 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/21827/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.38 Current children cumulated vsize (KiB) 7284 heavy processes: [startup+6.31147 s] /proc/loadavg: 1.00 1.00 1.00 2/38 21828 /proc/meminfo: memFree=595560/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=6276 CPUtime=3.23 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 1484 0 0 0 322 1 0 0 25 0 1 0 61737079 6426624 1344 1283457024 134512640 136285277 4294390128 18446744073709551615 134931344 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 1569 1344 234 433 0 1134 0 Current children cumulated CPU time (s) 5.57 Current children cumulated vsize (KiB) 8872 [startup+12.7127 s] /proc/loadavg: 1.00 1.00 1.00 2/38 21828 /proc/meminfo: memFree=594940/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=6904 CPUtime=9.63 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 1669 0 0 0 962 1 0 0 25 0 1 0 61737079 7069696 1510 1283457024 134512640 136285277 4294390128 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 1726 1510 234 433 0 1291 0 Current children cumulated CPU time (s) 11.97 Current children cumulated vsize (KiB) 9500 [startup+25.5055 s] /proc/loadavg: 1.00 1.00 1.00 2/38 21828 /proc/meminfo: memFree=594444/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=7236 CPUtime=22.41 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 1775 0 0 0 2240 1 0 0 25 0 1 0 61737079 7409664 1591 1283457024 134512640 136285277 4294390128 18446744073709551615 134669477 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 1809 1591 234 433 0 1374 0 Current children cumulated CPU time (s) 24.75 Current children cumulated vsize (KiB) 9832 [startup+51.1104 s] /proc/loadavg: 1.00 1.00 1.00 2/38 21828 /proc/meminfo: memFree=592832/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=8724 CPUtime=48.01 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 2165 0 0 0 4800 1 0 0 25 0 1 0 61737079 8933376 1972 1283457024 134512640 136285277 4294390128 18446744073709551615 134931288 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 2181 1972 234 433 0 1746 0 Current children cumulated CPU time (s) 50.35 Current children cumulated vsize (KiB) 11320 [startup+102.312 s] /proc/loadavg: 1.00 1.00 1.00 2/38 21828 /proc/meminfo: memFree=592584/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=9112 CPUtime=99.16 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 2238 0 0 0 9914 2 0 0 25 0 1 0 61737079 9330688 2045 1283457024 134512640 136285277 4294390128 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 2278 2045 234 433 0 1843 0 Current children cumulated CPU time (s) 101.5 Current children cumulated vsize (KiB) 11708 [startup+162.314 s] /proc/loadavg: 1.00 1.00 1.00 2/40 21832 /proc/meminfo: memFree=592188/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=9112 CPUtime=159.11 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 2287 0 0 0 15909 2 0 0 25 0 1 0 61737079 9330688 2068 1283457024 134512640 136285277 4294390128 18446744073709551615 134734753 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 2278 2068 234 433 0 1843 0 Current children cumulated CPU time (s) 161.45 Current children cumulated vsize (KiB) 11708 [startup+222.306 s] /proc/loadavg: 1.00 1.00 1.00 2/40 21838 /proc/meminfo: memFree=590576/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=10772 CPUtime=219.06 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 2809 0 0 0 21904 2 0 0 25 0 1 0 61737079 11030528 2475 1283457024 134512640 136285277 4294390128 18446744073709551615 134959523 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 2693 2475 234 433 0 2258 0 Current children cumulated CPU time (s) 221.4 Current children cumulated vsize (KiB) 13368 [startup+282.309 s] /proc/loadavg: 1.00 1.00 1.00 2/39 21839 /proc/meminfo: memFree=590592/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=10772 CPUtime=279.05 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 2809 0 0 0 27903 2 0 0 25 0 1 0 61737079 11030528 2475 1283457024 134512640 136285277 4294390128 18446744073709551615 134966782 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 2693 2475 234 433 0 2258 0 Current children cumulated CPU time (s) 281.39 Current children cumulated vsize (KiB) 13368 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+291.01 s] /proc/loadavg: 1.00 1.00 1.00 2/39 21839 /proc/meminfo: memFree=590592/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=10772 CPUtime=287.74 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 2809 0 0 0 28772 2 0 0 25 0 1 0 61737079 11030528 2475 1283457024 134512640 136285277 4294390128 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 2693 2475 234 433 0 2258 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 13368 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+291.01 s] /proc/loadavg: 1.00 1.00 1.00 2/39 21839 /proc/meminfo: memFree=590592/1048576 swapFree=0/0 [pid=21817] ppid=21816 vsize=2596 CPUtime=2.34 /proc/21817/stat : 21817 (aspcud-1.5) S 21816 21817 19908 34817 19908 4202496 576 16831 0 0 0 0 226 8 17 0 1 0 61737078 2658304 299 1283457024 134512640 135304128 4291800864 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/21817/statm: 649 299 251 194 0 36 0 [pid=21826] ppid=21817 vsize=10772 CPUtime=287.74 /proc/21826/stat : 21826 (clasp) R 21817 21817 19908 34817 19908 4202496 2809 0 0 0 28772 2 0 0 25 0 1 0 61737079 11030528 2475 1283457024 134512640 136285277 4294390128 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/21826/statm: 2693 2475 234 433 0 2258 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 13368 Child status: 0 Real time (s): 291.031 CPU time (s): 290.126 CPU user time (s): 290.01 CPU system time (s): 0.116007 CPU usage (%): 99.6891 Max. virtual memory (cumulated for all children) (KiB): 53272 getrusage(RUSAGE_CHILDREN,...) data: user time used= 290.01 system time used= 0.116007 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 23756 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= 221 involuntary context switches= 3769 runsolver used 0 second user time and 0 second system time The end