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/201108241238/aspcud-trendy-1.5/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.dudf-real.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/dudf-real//e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/e69a0e36-9ef1-11df-9d4a-00163e46d37a.cudf.dudf-real.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: 1.04 1.07 1.09 5/35 1606 /proc/meminfo: memFree=296312/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2592 CPUtime=0 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 5202007 2654208 280 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/1604/statm: 648 280 234 194 0 35 0 [pid=1605] ppid=1604 vsize=2592 CPUtime=0 /proc/1605/stat : 1605 (aspcud-trendy-1) R 1604 1604 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 5202007 2654208 133 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/1605/statm: 648 133 86 194 0 35 0 [pid=1606] ppid=1605 vsize=2592 CPUtime=0 /proc/1606/stat : 1606 (aspcud-trendy-1) R 1605 1604 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 5202008 2654208 47 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/1606/statm: 648 47 0 194 0 35 0 [startup+0.125307 s] /proc/loadavg: 1.04 1.07 1.09 5/35 1606 /proc/meminfo: memFree=296312/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=0.01 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 623 2229 0 0 0 0 1 0 25 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.205317 s] /proc/loadavg: 1.04 1.07 1.09 5/35 1606 /proc/meminfo: memFree=296312/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=0.01 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 623 2229 0 0 0 0 1 0 25 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.305341 s] /proc/loadavg: 1.04 1.07 1.09 5/35 1606 /proc/meminfo: memFree=296312/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=0.01 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 623 2229 0 0 0 0 1 0 25 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+0.705402 s] /proc/loadavg: 1.04 1.07 1.09 5/35 1606 /proc/meminfo: memFree=296312/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=0.01 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 623 2229 0 0 0 0 1 0 25 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2600 [startup+1.50553 s] /proc/loadavg: 1.04 1.07 1.09 2/37 1618 /proc/meminfo: memFree=274700/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=0.01 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 623 2229 0 0 0 0 1 0 25 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 [pid=1616] ppid=1604 vsize=1928 CPUtime=0 /proc/1616/stat : 1616 (clasp) S 1604 1604 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 5202009 1974272 159 1283457024 134512640 136285277 4293875936 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/1616/statm: 482 159 144 433 0 47 0 [pid=1617] ppid=1604 vsize=2588 CPUtime=0 /proc/1617/stat : 1617 (gringo) S 1604 1604 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 5202009 2650112 272 1283457024 134512640 136933539 4286579296 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/1617/statm: 647 272 242 592 0 52 0 [pid=1618] ppid=1604 vsize=39164 CPUtime=1.5 /proc/1618/stat : 1618 (cudf2lp) R 1604 1604 1511 34817 1511 4202496 10919 0 0 0 148 2 0 0 25 0 1 0 5202009 40103936 9271 1283457024 134512640 135786343 4292421648 18446744073709551615 134554368 0 0 6 0 0 0 0 17 0 0 0 0 /proc/1618/statm: 9791 9271 133 311 0 9478 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 46280 [startup+3.10575 s] /proc/loadavg: 1.04 1.07 1.09 3/37 1618 /proc/meminfo: memFree=242212/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=1.78 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 624 13631 0 0 0 0 174 4 18 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 [pid=1616] ppid=1604 vsize=26800 CPUtime=0.16 /proc/1616/stat : 1616 (clasp) R 1604 1604 1511 34817 1511 4202496 7467 0 0 0 15 1 0 0 18 0 1 0 5202009 27443200 6270 1283457024 134512640 136285277 4293875936 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1616/statm: 6700 6270 177 433 0 6265 0 [pid=1617] ppid=1604 vsize=47152 CPUtime=1.15 /proc/1617/stat : 1617 (gringo) R 1604 1604 1511 34817 1511 4202496 12904 0 0 0 111 4 0 0 18 0 1 0 5202009 48283648 9009 1283457024 134512640 136933539 4286579296 18446744073709551615 134687740 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/1617/statm: 11788 9009 253 592 0 11193 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 76552 [startup+6.30629 s] /proc/loadavg: 1.11 1.08 1.09 2/35 1618 /proc/meminfo: memFree=254768/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=3.2 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 624 28620 0 0 0 0 309 11 18 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 [pid=1616] ppid=1604 vsize=43056 CPUtime=3.1 /proc/1616/stat : 1616 (clasp) R 1604 1604 1511 34817 1511 4202496 13091 0 0 0 308 2 0 0 23 0 1 0 5202009 44089344 10490 1283457024 134512640 136285277 4293875936 18446744073709551615 134669296 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1616/statm: 10764 10490 234 433 0 10329 0 Current children cumulated CPU time (s) 6.3 Current children cumulated vsize (KiB) 45656 Solver just ended. Dumping a history of the last processes samples [startup+6.4063 s] /proc/loadavg: 1.11 1.08 1.09 2/35 1618 /proc/meminfo: memFree=254768/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=3.2 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 624 28620 0 0 0 0 309 11 18 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 [pid=1616] ppid=1604 vsize=43056 CPUtime=3.2 /proc/1616/stat : 1616 (clasp) R 1604 1604 1511 34817 1511 4202496 13091 0 0 0 318 2 0 0 25 0 1 0 5202009 44089344 10490 1283457024 134512640 136285277 4293875936 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1616/statm: 10764 10490 234 433 0 10329 0 Current children cumulated CPU time (s) 6.4 Current children cumulated vsize (KiB) 45656 [startup+8.00657 s] /proc/loadavg: 1.11 1.08 1.09 2/35 1618 /proc/meminfo: memFree=254784/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=3.2 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 624 28620 0 0 0 0 309 11 18 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 [pid=1616] ppid=1604 vsize=43056 CPUtime=4.8 /proc/1616/stat : 1616 (clasp) R 1604 1604 1511 34817 1511 4202496 13091 0 0 0 478 2 0 0 25 0 1 0 5202009 44089344 10490 1283457024 134512640 136285277 4293875936 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1616/statm: 10764 10490 234 433 0 10329 0 Current children cumulated CPU time (s) 8 Current children cumulated vsize (KiB) 45656 [startup+8.40662 s] /proc/loadavg: 1.11 1.08 1.09 2/35 1618 /proc/meminfo: memFree=254784/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=3.2 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 624 28620 0 0 0 0 309 11 18 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 [pid=1616] ppid=1604 vsize=43056 CPUtime=5.2 /proc/1616/stat : 1616 (clasp) R 1604 1604 1511 34817 1511 4202496 13091 0 0 0 518 2 0 0 25 0 1 0 5202009 44089344 10490 1283457024 134512640 136285277 4293875936 18446744073709551615 134959967 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1616/statm: 10764 10490 234 433 0 10329 0 Current children cumulated CPU time (s) 8.4 Current children cumulated vsize (KiB) 45656 [startup+8.80669 s] /proc/loadavg: 1.10 1.08 1.09 2/35 1618 /proc/meminfo: memFree=262224/1048576 swapFree=0/0 [pid=1604] ppid=1603 vsize=2600 CPUtime=3.2 /proc/1604/stat : 1604 (aspcud-trendy-1) S 1603 1604 1511 34817 1511 4202496 624 28620 0 0 0 0 309 11 18 0 1 0 5202007 2662400 299 1283457024 134512640 135304128 4287939392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/1604/statm: 650 299 251 194 0 37 0 [pid=1616] ppid=1604 vsize=35520 CPUtime=5.59 /proc/1616/stat : 1616 (clasp) R 1604 1604 1511 34817 1511 4202496 13099 0 0 0 556 3 0 0 25 0 1 0 5202009 36372480 8614 1283457024 134512640 136285277 4293875936 18446744073709551615 135631804 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/1616/statm: 8880 8614 242 433 0 8445 0 Current children cumulated CPU time (s) 8.79 Current children cumulated vsize (KiB) 38120 Child status: 0 Real time (s): 8.84601 CPU time (s): 8.84055 CPU user time (s): 8.66454 CPU system time (s): 0.176011 CPU usage (%): 99.9383 Max. virtual memory (cumulated for all children) (KiB): 87888 getrusage(RUSAGE_CHILDREN,...) data: user time used= 8.66454 system time used= 0.176011 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 46323 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= 1832 involuntary context switches= 1458 runsolver used 0 second user time and 0 second system time The end