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/201109011757/aspcud-1.5/e381ba7e-a192-11e0-8647-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//e381ba7e-a192-11e0-8647-00163e1e087d.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/e381ba7e-a192-11e0-8647-00163e1e087d.cudf.dudf-real.result -sum(pin-priority-1),-sum(pin-priority-500),-sum(pin-priority-700),-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.03 1.01 1.00 3/34 3865 /proc/meminfo: memFree=260888/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2584 CPUtime=0 /proc/3864/stat : 3864 (aspcud-1.5) R 3863 3864 22717 34817 22717 4202496 366 0 0 0 0 0 0 0 25 0 1 0 73661317 2646016 279 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/3864/statm: 646 279 234 194 0 33 0 [pid=3865] ppid=3864 vsize=2584 CPUtime=0 /proc/3865/stat : 3865 (aspcud-1.5) R 3864 3864 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 73661317 2646016 45 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/3865/statm: 646 45 0 194 0 33 0 [startup+0.170443 s] /proc/loadavg: 1.03 1.01 1.00 3/34 3865 /proc/meminfo: memFree=260888/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=0 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 1524 0 0 0 0 0 0 25 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.206445 s] /proc/loadavg: 1.03 1.01 1.00 3/34 3865 /proc/meminfo: memFree=260888/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=0 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 1524 0 0 0 0 0 0 25 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.306464 s] /proc/loadavg: 1.03 1.01 1.00 3/34 3865 /proc/meminfo: memFree=260888/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=0 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 1524 0 0 0 0 0 0 25 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.706509 s] /proc/loadavg: 1.03 1.01 1.00 3/34 3865 /proc/meminfo: memFree=260888/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=0 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 1524 0 0 0 0 0 0 25 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50654 s] /proc/loadavg: 1.03 1.01 1.00 2/37 3875 /proc/meminfo: memFree=223072/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=0 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 1524 0 0 0 0 0 0 25 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=1928 CPUtime=0 /proc/3873/stat : 3873 (clasp) S 3864 3864 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 73661318 1974272 160 1283457024 134512640 136285277 4288807968 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/3873/statm: 482 160 144 433 0 47 0 [pid=3874] ppid=3864 vsize=2588 CPUtime=0 /proc/3874/stat : 3874 (gringo) S 3864 3864 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 73661318 2650112 272 1283457024 134512640 136933539 4289813904 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3874/statm: 647 272 242 592 0 52 0 [pid=3875] ppid=3864 vsize=32024 CPUtime=1.18 /proc/3875/stat : 3875 (cudf2lp) R 3864 3864 22717 34817 22717 4202496 9051 0 0 0 114 4 0 0 25 0 1 0 73661318 32792576 7453 1283457024 134512640 135786343 4292927552 18446744073709551615 135219485 0 0 6 0 0 0 0 17 0 0 0 0 /proc/3875/statm: 8006 7453 133 311 0 7693 0 Current children cumulated CPU time (s) 1.18 Current children cumulated vsize (KiB) 39132 [startup+3.104 s] /proc/loadavg: 1.03 1.01 1.00 3/36 3875 /proc/meminfo: memFree=225212/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=13240 CPUtime=0.86 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 3568 0 0 0 86 0 0 0 18 0 1 0 73661318 13557760 3085 1283457024 134512640 136285277 4288807968 18446744073709551615 134959938 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 3310 3085 234 433 0 2875 0 Current children cumulated CPU time (s) 2.77 Current children cumulated vsize (KiB) 15832 [startup+6.30467 s] /proc/loadavg: 1.03 1.01 1.00 2/35 3875 /proc/meminfo: memFree=221632/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=29244 CPUtime=4.06 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 7567 0 0 0 406 0 0 0 25 0 1 0 73661318 29945856 7084 1283457024 134512640 136285277 4288807968 18446744073709551615 134735653 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 7311 7084 234 433 0 6876 0 Current children cumulated CPU time (s) 5.97 Current children cumulated vsize (KiB) 31836 [startup+12.706 s] /proc/loadavg: 1.02 1.01 1.00 2/35 3875 /proc/meminfo: memFree=193740/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=50400 CPUtime=10.46 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 12835 0 0 0 1045 1 0 0 25 0 1 0 73661318 51609600 12352 1283457024 134512640 136285277 4288807968 18446744073709551615 134931382 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 12600 12352 234 433 0 12165 0 Current children cumulated CPU time (s) 12.37 Current children cumulated vsize (KiB) 52992 [startup+25.5092 s] /proc/loadavg: 1.02 1.01 1.00 2/35 3875 /proc/meminfo: memFree=179604/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=64544 CPUtime=23.26 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 16610 0 0 0 2325 1 0 0 25 0 1 0 73661318 66093056 15893 1283457024 134512640 136285277 4288807968 18446744073709551615 134650481 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 16136 15893 234 433 0 15701 0 Current children cumulated CPU time (s) 25.17 Current children cumulated vsize (KiB) 67136 [startup+51.1151 s] /proc/loadavg: 1.01 1.01 1.00 2/37 3878 /proc/meminfo: memFree=168544/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=75960 CPUtime=48.84 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 19325 0 0 0 4883 1 0 0 25 0 1 0 73661318 77783040 18608 1283457024 134512640 136285277 4288807968 18446744073709551615 134966973 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 18990 18608 234 433 0 18555 0 Current children cumulated CPU time (s) 50.75 Current children cumulated vsize (KiB) 78552 [startup+102.308 s] /proc/loadavg: 1.00 1.00 1.00 2/37 3883 /proc/meminfo: memFree=157136/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=86904 CPUtime=100 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 22555 0 0 0 9997 3 0 0 25 0 1 0 73661318 88989696 21438 1283457024 134512640 136285277 4288807968 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 21726 21438 234 433 0 21291 0 Current children cumulated CPU time (s) 101.91 Current children cumulated vsize (KiB) 89496 [startup+162.309 s] /proc/loadavg: 1.00 1.00 1.00 2/36 3886 /proc/meminfo: memFree=158392/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=88280 CPUtime=159.87 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 24182 0 0 0 15982 5 0 0 25 0 1 0 73661318 90398720 21776 1283457024 134512640 136285277 4288807968 18446744073709551615 134945938 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 22070 21776 234 433 0 21635 0 Current children cumulated CPU time (s) 161.78 Current children cumulated vsize (KiB) 90872 [startup+222.314 s] /proc/loadavg: 1.00 1.00 1.00 2/35 3886 /proc/meminfo: memFree=150464/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=93580 CPUtime=219.82 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 25515 0 0 0 21975 7 0 0 25 0 1 0 73661318 95825920 23109 1283457024 134512640 136285277 4288807968 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 23395 23109 234 433 0 22960 0 Current children cumulated CPU time (s) 221.73 Current children cumulated vsize (KiB) 96172 [startup+282.308 s] /proc/loadavg: 1.00 1.00 1.00 2/35 3886 /proc/meminfo: memFree=147364/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=95852 CPUtime=279.77 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 27419 0 0 0 27968 9 0 0 25 0 1 0 73661318 98152448 23730 1283457024 134512640 136285277 4288807968 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 23963 23730 234 433 0 23528 0 Current children cumulated CPU time (s) 281.68 Current children cumulated vsize (KiB) 98444 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.71 s] /proc/loadavg: 1.00 1.00 1.00 2/35 3886 /proc/meminfo: memFree=133972/1048576 swapFree=0/0 [pid=3864] ppid=3863 vsize=2592 CPUtime=1.91 /proc/3864/stat : 3864 (aspcud-1.5) S 3863 3864 22717 34817 22717 4202496 576 17495 0 0 0 0 184 7 17 0 1 0 73661317 2654208 298 1283457024 134512640 135304128 4291735168 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3864/statm: 648 298 251 194 0 35 0 [pid=3873] ppid=3864 vsize=110492 CPUtime=288.17 /proc/3873/stat : 3873 (clasp) R 3864 3864 22717 34817 22717 4202496 30925 0 0 0 28807 10 0 0 25 0 1 0 73661318 113143808 27236 1283457024 134512640 136285277 4288807968 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/3873/statm: 27623 27236 234 433 0 27188 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 113084 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.741 CPU time (s): 290.134 CPU user time (s): 289.922 CPU system time (s): 0.212013 CPU usage (%): 99.7912 Max. virtual memory (cumulated for all children) (KiB): 113084 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.922 system time used= 0.212013 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 52634 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= 483 involuntary context switches= 3863 runsolver used 0 second user time and 0.012 second system time The end