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/rand992.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand992.cudf /home/misc2010/tmp/201109011757/aspcud-1.5/rand992.cudf.dudf-random.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.01 1.02 1.00 5/34 31386 /proc/meminfo: memFree=511924/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2588 CPUtime=0.01 /proc/31385/stat : 31385 (aspcud-1.5) R 31384 31385 22717 34817 22717 4202496 366 0 0 0 0 1 0 0 25 0 1 0 72926337 2650112 279 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/31385/statm: 647 279 234 194 0 34 0 [pid=31386] ppid=31385 vsize=2588 CPUtime=0 /proc/31386/stat : 31386 (aspcud-1.5) R 31385 31385 22717 34817 22717 4202560 0 0 0 0 0 0 0 0 25 0 1 0 72926337 2650112 45 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/31386/statm: 647 45 0 194 0 34 0 [startup+0.16033 s] /proc/loadavg: 1.01 1.02 1.00 5/34 31386 /proc/meminfo: memFree=511924/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=0.01 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.204316 s] /proc/loadavg: 1.01 1.02 1.00 5/34 31386 /proc/meminfo: memFree=511924/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=0.01 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.304324 s] /proc/loadavg: 1.01 1.02 1.00 5/34 31386 /proc/meminfo: memFree=511924/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=0.01 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.704367 s] /proc/loadavg: 1.01 1.02 1.00 5/34 31386 /proc/meminfo: memFree=511924/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=0.01 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50449 s] /proc/loadavg: 1.01 1.02 1.00 2/37 31396 /proc/meminfo: memFree=480752/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=0.01 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=1928 CPUtime=0 /proc/31394/stat : 31394 (clasp) S 31385 31385 22717 34817 22717 4202496 292 0 0 0 0 0 0 0 25 0 1 0 72926338 1974272 160 1283457024 134512640 136285277 4292554672 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/31394/statm: 482 160 144 433 0 47 0 [pid=31395] ppid=31385 vsize=2584 CPUtime=0 /proc/31395/stat : 31395 (gringo) S 31385 31385 22717 34817 22717 4202496 404 0 0 0 0 0 0 0 25 0 1 0 72926338 2646016 272 1283457024 134512640 136933539 4293490960 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/31395/statm: 646 272 242 592 0 51 0 [pid=31396] ppid=31385 vsize=29452 CPUtime=1.17 /proc/31396/stat : 31396 (cudf2lp) D 31385 31385 22717 34817 22717 4202496 8096 0 0 0 114 3 0 0 25 0 1 0 72926338 30158848 6595 1283457024 134512640 135786343 4292585456 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0 /proc/31396/statm: 7363 6595 128 311 0 7050 0 Current children cumulated CPU time (s) 1.18 Current children cumulated vsize (KiB) 36560 [startup+3.11262 s] /proc/loadavg: 1.01 1.02 1.00 2/37 31396 /proc/meminfo: memFree=455328/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=0.01 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 1522 0 0 0 1 0 0 25 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=8616 CPUtime=0.01 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 2185 0 0 0 1 0 0 0 18 0 1 0 72926338 8822784 1849 1283457024 134512640 136285277 4292554672 18446744073709551615 134839901 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 2154 1849 177 433 0 1719 0 [pid=31395] ppid=31385 vsize=12396 CPUtime=0.35 /proc/31395/stat : 31395 (gringo) S 31385 31385 22717 34817 22717 4202496 3299 0 0 0 32 3 0 0 18 0 1 0 72926338 12693504 2247 1283457024 134512640 136933539 4293490960 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/31395/statm: 3099 2247 242 592 0 2504 0 [pid=31396] ppid=31385 vsize=46080 CPUtime=2.16 /proc/31396/stat : 31396 (cudf2lp) R 31385 31385 22717 34817 22717 4202496 14083 0 0 0 211 5 0 0 25 0 1 0 72926338 47185920 11312 1283457024 134512640 135786343 4292585456 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/31396/statm: 11520 11312 139 311 0 11207 0 Current children cumulated CPU time (s) 2.53 Current children cumulated vsize (KiB) 69688 [startup+6.31344 s] /proc/loadavg: 1.01 1.02 1.00 2/35 31396 /proc/meminfo: memFree=449416/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=42708 CPUtime=2.06 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 12381 0 0 0 202 4 0 0 20 0 1 0 72926338 43732992 10460 1283457024 134512640 136285277 4292554672 18446744073709551615 134955235 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 10677 10460 234 433 0 10242 0 Current children cumulated CPU time (s) 5.73 Current children cumulated vsize (KiB) 45304 [startup+12.715 s] /proc/loadavg: 1.01 1.02 1.00 2/35 31396 /proc/meminfo: memFree=361012/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=124876 CPUtime=8.46 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 32897 0 0 0 832 14 0 0 25 0 1 0 72926338 127873024 30976 1283457024 134512640 136285277 4292554672 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 31219 30976 234 433 0 30784 0 Current children cumulated CPU time (s) 12.13 Current children cumulated vsize (KiB) 127472 [startup+25.509 s] /proc/loadavg: 1.00 1.01 1.00 2/35 31396 /proc/meminfo: memFree=296160/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=189488 CPUtime=21.23 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 49074 0 0 0 2108 15 0 0 25 0 1 0 72926338 194035712 47153 1283457024 134512640 136285277 4292554672 18446744073709551615 134649408 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 47372 47153 234 433 0 46937 0 Current children cumulated CPU time (s) 24.9 Current children cumulated vsize (KiB) 192084 [startup+51.1061 s] /proc/loadavg: 1.00 1.01 1.00 2/35 31396 /proc/meminfo: memFree=181584/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=303844 CPUtime=46.8 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 77642 0 0 0 4654 26 0 0 25 0 1 0 72926338 311136256 75721 1283457024 134512640 136285277 4292554672 18446744073709551615 134686319 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 75961 75721 234 433 0 75526 0 Current children cumulated CPU time (s) 50.47 Current children cumulated vsize (KiB) 306440 [startup+102.309 s] /proc/loadavg: 1.00 1.01 1.00 2/35 31396 /proc/meminfo: memFree=5876/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=479288 CPUtime=97.96 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 121971 0 0 0 9753 43 0 0 25 0 1 0 72926338 490790912 119565 1283457024 134512640 136285277 4292554672 18446744073709551615 134639124 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 119822 119565 234 433 0 119387 0 Current children cumulated CPU time (s) 101.63 Current children cumulated vsize (KiB) 481884 [startup+162.304 s] /proc/loadavg: 1.00 1.00 1.00 2/35 31396 /proc/meminfo: memFree=7296/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=618560 CPUtime=157.88 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 157363 0 0 0 15733 55 0 0 25 0 1 0 72926338 633405440 154411 1283457024 134512640 136285277 4292554672 18446744073709551615 134985131 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 154640 154411 234 433 0 154205 0 Current children cumulated CPU time (s) 161.55 Current children cumulated vsize (KiB) 621156 [startup+222.309 s] /proc/loadavg: 1.00 1.00 1.00 2/37 31403 /proc/meminfo: memFree=7272/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=618560 CPUtime=217.83 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 157379 0 0 0 21728 55 0 0 25 0 1 0 72926338 633405440 154427 1283457024 134512640 136285277 4292554672 18446744073709551615 134649432 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 154640 154427 234 433 0 154205 0 Current children cumulated CPU time (s) 221.5 Current children cumulated vsize (KiB) 621156 [startup+282.304 s] /proc/loadavg: 1.00 1.00 1.00 2/36 31407 /proc/meminfo: memFree=7288/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=618560 CPUtime=277.77 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 157379 0 0 0 27721 56 0 0 25 0 1 0 72926338 633405440 154427 1283457024 134512640 136285277 4292554672 18446744073709551615 134930797 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 154640 154427 234 433 0 154205 0 Current children cumulated CPU time (s) 281.44 Current children cumulated vsize (KiB) 621156 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.907 s] /proc/loadavg: 1.00 1.00 1.00 2/36 31407 /proc/meminfo: memFree=7288/1048576 swapFree=0/0 [pid=31385] ppid=31384 vsize=2596 CPUtime=3.67 /proc/31385/stat : 31385 (aspcud-1.5) S 31384 31385 22717 34817 22717 4202496 581 29323 0 0 0 1 351 15 18 0 1 0 72926337 2658304 298 1283457024 134512640 135304128 4289072176 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/31385/statm: 649 298 251 194 0 36 0 [pid=31394] ppid=31385 vsize=618560 CPUtime=286.37 /proc/31394/stat : 31394 (clasp) R 31385 31385 22717 34817 22717 4202496 157379 0 0 0 28581 56 0 0 25 0 1 0 72926338 633405440 154427 1283457024 134512640 136285277 4292554672 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/31394/statm: 154640 154427 234 433 0 154205 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 621156 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.971 CPU time (s): 290.122 CPU user time (s): 289.342 CPU system time (s): 0.780048 CPU usage (%): 99.7084 Max. virtual memory (cumulated for all children) (KiB): 623428 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.342 system time used= 0.780048 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 191012 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= 1679 involuntary context switches= 4927 runsolver used 0 second user time and 0 second system time The end