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/201108291842/aspcud-1.5/rand21.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand21.cudf /home/misc2010/tmp/201108291842/aspcud-1.5/rand21.cudf.dudf-random.result -notuptodate,-removed,-changed 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.38 0.83 0.78 5/34 17976 /proc/meminfo: memFree=437176/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2588 CPUtime=0 /proc/17975/stat : 17975 (aspcud-1.5) R 17974 17975 17511 34816 17511 4202496 366 0 0 0 0 0 0 0 25 0 1 0 45965288 2650112 280 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/17975/statm: 647 280 234 194 0 34 0 [pid=17976] ppid=17975 vsize=2588 CPUtime=0 /proc/17976/stat : 17976 (aspcud-1.5) R 17975 17975 17511 34816 17511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 45965288 2650112 46 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/17976/statm: 647 46 0 194 0 34 0 [startup+0.125309 s] /proc/loadavg: 1.38 0.83 0.78 5/34 17976 /proc/meminfo: memFree=437176/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=0 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 579 1520 0 0 0 0 0 0 25 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.205316 s] /proc/loadavg: 1.38 0.83 0.78 5/34 17976 /proc/meminfo: memFree=437176/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=0 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 579 1520 0 0 0 0 0 0 25 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.305337 s] /proc/loadavg: 1.38 0.83 0.78 5/34 17976 /proc/meminfo: memFree=437176/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=0 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 579 1520 0 0 0 0 0 0 25 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.705348 s] /proc/loadavg: 1.38 0.83 0.78 5/34 17976 /proc/meminfo: memFree=437176/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=0 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 579 1520 0 0 0 0 0 0 25 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50541 s] /proc/loadavg: 1.35 0.83 0.78 2/37 17986 /proc/meminfo: memFree=401196/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=0 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 579 1520 0 0 0 0 0 0 25 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=1928 CPUtime=0.01 /proc/17984/stat : 17984 (clasp) S 17975 17975 17511 34816 17511 4202496 292 0 0 0 1 0 0 0 25 0 1 0 45965289 1974272 160 1283457024 134512640 136285277 4286886464 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/17984/statm: 482 160 144 433 0 47 0 [pid=17985] ppid=17975 vsize=2584 CPUtime=0 /proc/17985/stat : 17985 (gringo) S 17975 17975 17511 34816 17511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 45965289 2646016 272 1283457024 134512640 136933539 4291077824 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/17985/statm: 646 272 242 592 0 51 0 [pid=17986] ppid=17975 vsize=25000 CPUtime=1.3 /proc/17986/stat : 17986 (cudf2lp) R 17975 17975 17511 34816 17511 4202496 7166 0 0 0 125 5 0 0 25 0 1 0 45965289 25600000 5568 1283457024 134512640 135786343 4289154288 18446744073709551615 134536268 0 0 6 0 0 0 0 17 0 0 0 0 /proc/17986/statm: 6250 5568 128 311 0 5937 0 Current children cumulated CPU time (s) 1.31 Current children cumulated vsize (KiB) 32108 [startup+3.10597 s] /proc/loadavg: 1.35 0.83 0.78 2/37 17986 /proc/meminfo: memFree=364772/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=2.17 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 14426 0 0 0 0 210 7 18 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=13876 CPUtime=0.07 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 3696 0 0 0 6 1 0 0 18 0 1 0 45965289 14209024 3178 1283457024 134512640 136285277 4286886464 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 3469 3178 177 433 0 3034 0 [pid=17985] ppid=17975 vsize=22192 CPUtime=0.58 /proc/17985/stat : 17985 (gringo) R 17975 17975 17511 34816 17511 4202496 6327 0 0 0 56 2 0 0 18 0 1 0 45965289 22724608 4376 1283457024 134512640 136933539 4291077824 18446744073709551615 134688104 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/17985/statm: 5548 4376 253 592 0 4953 0 Current children cumulated CPU time (s) 2.82 Current children cumulated vsize (KiB) 38664 [startup+6.30718 s] /proc/loadavg: 1.35 0.83 0.78 2/35 17986 /proc/meminfo: memFree=377204/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=33700 CPUtime=2.74 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 10029 0 0 0 268 6 0 0 22 0 1 0 45965289 34508800 8169 1283457024 134512640 136285277 4286886464 18446744073709551615 134893162 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 8425 8169 234 433 0 7990 0 Current children cumulated CPU time (s) 6.01 Current children cumulated vsize (KiB) 36296 [startup+12.7088 s] /proc/loadavg: 1.29 0.83 0.78 2/35 17986 /proc/meminfo: memFree=322528/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=102764 CPUtime=9.13 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 27314 0 0 0 902 11 0 0 25 0 1 0 45965289 105230336 25454 1283457024 134512640 136285277 4286886464 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 25691 25454 234 433 0 25256 0 Current children cumulated CPU time (s) 12.4 Current children cumulated vsize (KiB) 105360 [startup+25.5114 s] /proc/loadavg: 1.25 0.84 0.78 2/35 17986 /proc/meminfo: memFree=263132/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=147828 CPUtime=21.93 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 38597 0 0 0 2177 16 0 0 25 0 1 0 45965289 151375872 36737 1283457024 134512640 136285277 4286886464 18446744073709551615 134650356 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 36957 36737 234 433 0 36522 0 Current children cumulated CPU time (s) 25.2 Current children cumulated vsize (KiB) 150424 [startup+51.1074 s] /proc/loadavg: 1.16 0.85 0.79 2/35 17986 /proc/meminfo: memFree=219856/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=191112 CPUtime=47.52 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 49397 0 0 0 4732 20 0 0 25 0 1 0 45965289 195698688 47537 1283457024 134512640 136285277 4286886464 18446744073709551615 134959967 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 47778 47537 234 433 0 47343 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 193708 [startup+102.31 s] /proc/loadavg: 1.06 0.87 0.80 2/35 17986 /proc/meminfo: memFree=19100/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=391528 CPUtime=98.65 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 99721 0 0 0 9833 32 0 0 25 0 1 0 45965289 400924672 97625 1283457024 134512640 136285277 4286886464 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 97882 97625 234 433 0 97447 0 Current children cumulated CPU time (s) 101.92 Current children cumulated vsize (KiB) 394124 [startup+162.306 s] /proc/loadavg: 1.02 0.89 0.81 2/36 17988 /proc/meminfo: memFree=5544/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=563224 CPUtime=158.53 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 142627 0 0 0 15807 46 0 0 25 0 1 0 45965289 576741376 140531 1283457024 134512640 136285277 4286886464 18446744073709551615 134963464 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 140806 140531 234 433 0 140371 0 Current children cumulated CPU time (s) 161.8 Current children cumulated vsize (KiB) 565820 [startup+222.31 s] /proc/loadavg: 1.01 0.91 0.82 2/37 17992 /proc/meminfo: memFree=6008/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=745748 CPUtime=218.43 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 188237 0 0 0 21773 70 0 0 25 0 1 0 45965289 763645952 186141 1283457024 134512640 136285277 4286886464 18446744073709551615 134960063 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 186437 186141 234 433 0 186002 0 Current children cumulated CPU time (s) 221.7 Current children cumulated vsize (KiB) 748344 [startup+282.308 s] /proc/loadavg: 1.00 0.92 0.83 2/37 17998 /proc/meminfo: memFree=6204/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=860736 CPUtime=278.32 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 216959 0 0 0 27742 90 0 0 25 0 1 0 45965289 881393664 214863 1283457024 134512640 136285277 4286886464 18446744073709551615 134649454 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 215184 214863 234 433 0 214749 0 Current children cumulated CPU time (s) 281.59 Current children cumulated vsize (KiB) 863332 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.811 s] /proc/loadavg: 1.00 0.92 0.83 2/36 17998 /proc/meminfo: memFree=5928/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=3.27 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 580 25659 0 0 0 0 314 13 15 0 1 0 45965288 2658304 299 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 649 299 251 194 0 36 0 [pid=17984] ppid=17975 vsize=895856 CPUtime=286.79 /proc/17984/stat : 17984 (clasp) R 17975 17975 17511 34816 17511 4202496 225746 0 0 0 28583 96 0 0 25 0 1 0 45965289 917356544 223650 1283457024 134512640 136285277 4286886464 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/17984/statm: 223964 223650 234 433 0 223529 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 898452 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.936 s] /proc/loadavg: 1.00 0.92 0.83 2/36 17998 /proc/meminfo: memFree=5928/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2596 CPUtime=290.17 /proc/17975/stat : 17975 (aspcud-1.5) D 17974 17975 17511 34816 17511 4202496 609 251622 0 1 0 0 28898 119 18 0 1 0 45965288 2658304 306 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 0 16902 1132543225 18446744071564332000 0 0 17 0 0 0 0 /proc/17975/statm: 649 306 258 194 0 36 0 Current children cumulated CPU time (s) 290.17 Current children cumulated vsize (KiB) 2596 [startup+291.008 s] /proc/loadavg: 1.00 0.92 0.83 2/36 17998 /proc/meminfo: memFree=5928/1048576 swapFree=0/0 [pid=17975] ppid=17974 vsize=2856 CPUtime=290.2 /proc/17975/stat : 17975 (aspcud-1.5) S 17974 17975 17511 34816 17511 4202496 1012 254723 0 5 1 0 28899 120 25 0 1 0 45965288 2924544 362 1283457024 134512640 135304128 4292612048 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0 /proc/17975/statm: 714 362 262 194 0 101 0 Current children cumulated CPU time (s) 290.2 Current children cumulated vsize (KiB) 2856 Child status: 0 Real time (s): 291.016 CPU time (s): 290.21 CPU user time (s): 289.006 CPU system time (s): 1.20407 CPU usage (%): 99.723 Max. virtual memory (cumulated for all children) (KiB): 898452 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.006 system time used= 1.20408 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 255926 page faults= 6 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 1359 involuntary context switches= 4933 runsolver used 0 second user time and 0 second system time The end