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/rand314.cudf.s-e-l-s-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand314.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand314.cudf.s-e-l-s-s.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.12 1.11 1.03 5/37 5783 /proc/meminfo: memFree=470568/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2588 CPUtime=0 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 18 0 1 0 1335425 2650112 280 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/5781/statm: 647 280 234 194 0 34 0 [pid=5782] ppid=5781 vsize=2588 CPUtime=0 /proc/5782/stat : 5782 (aspcud-trendy-1) R 5781 5781 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 1335425 2650112 133 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/5782/statm: 647 133 86 194 0 34 0 [pid=5783] ppid=5782 vsize=2588 CPUtime=0 /proc/5783/stat : 5783 (aspcud-trendy-1) R 5782 5781 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1335425 2650112 47 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/5783/statm: 647 47 0 194 0 34 0 [startup+0.137413 s] /proc/loadavg: 1.12 1.11 1.03 5/37 5783 /proc/meminfo: memFree=470568/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=0 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 623 2226 0 0 0 0 0 0 25 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.207418 s] /proc/loadavg: 1.12 1.11 1.03 5/37 5783 /proc/meminfo: memFree=470568/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=0 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 623 2226 0 0 0 0 0 0 25 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.307431 s] /proc/loadavg: 1.12 1.11 1.03 5/37 5783 /proc/meminfo: memFree=470568/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=0 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 623 2226 0 0 0 0 0 0 25 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.70749 s] /proc/loadavg: 1.12 1.11 1.03 5/37 5783 /proc/meminfo: memFree=470568/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=0 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 623 2226 0 0 0 0 0 0 25 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.5076 s] /proc/loadavg: 1.12 1.11 1.03 2/39 5796 /proc/meminfo: memFree=449576/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=0 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 623 2226 0 0 0 0 0 0 25 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=1924 CPUtime=0 /proc/5793/stat : 5793 (clasp) S 5781 5781 1511 34817 1511 4202496 291 0 0 0 0 0 0 0 25 0 1 0 1335426 1970176 159 1283457024 134512640 136285277 4294138144 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/5793/statm: 481 159 144 433 0 46 0 [pid=5794] ppid=5781 vsize=2584 CPUtime=0 /proc/5794/stat : 5794 (gringo) S 5781 5781 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 1335426 2646016 272 1283457024 134512640 136933539 4293427440 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/5794/statm: 646 272 242 592 0 51 0 [pid=5795] ppid=5781 vsize=40664 CPUtime=1.5 /proc/5795/stat : 5795 (cudf2lp) R 5781 5781 1511 34817 1511 4202496 11714 0 0 0 146 4 0 0 25 0 1 0 1335426 41639936 8804 1283457024 134512640 135786343 4290547264 18446744073709551615 134584192 0 0 6 0 0 0 0 17 0 0 0 0 /proc/5795/statm: 10166 8804 126 311 0 9853 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 47768 [startup+3.10784 s] /proc/loadavg: 1.11 1.11 1.03 3/39 5796 /proc/meminfo: memFree=415476/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=0 /proc/5781/stat : 5781 (aspcud-trendy-1) R 5780 5781 1511 34817 1511 4202496 623 2226 0 0 0 0 0 0 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=17448 CPUtime=0.05 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 4807 0 0 0 2 3 0 0 18 0 1 0 1335426 17866752 4017 1283457024 134512640 136285277 4294138144 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 4362 4017 177 433 0 3927 0 [pid=5794] ppid=5781 vsize=22104 CPUtime=0.77 /proc/5794/stat : 5794 (gringo) R 5781 5781 1511 34817 1511 4202496 6908 0 0 0 74 3 0 0 18 0 1 0 1335426 22634496 4636 1283457024 134512640 136933539 4293427440 18446744073709551615 135633710 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/5794/statm: 5526 4636 247 592 0 4931 0 [pid=5795] ppid=5781 vsize=0 CPUtime=2.26 /proc/5795/stat : 5795 (cudf2lp) Z 5781 5781 1511 34817 1511 4202508 16203 0 0 0 220 6 0 0 25 0 1 0 1335426 0 0 1283457024 0 0 0 0 0 0 0 6 0 18446744071564254338 0 0 17 0 0 0 0 /proc/5795/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 42148 [startup+6.3084 s] /proc/loadavg: 1.11 1.11 1.03 2/37 5796 /proc/meminfo: memFree=415136/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=57004 CPUtime=2.01 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 17311 0 0 0 194 7 0 0 20 0 1 0 1335426 58372096 13907 1283457024 134512640 136285277 4294138144 18446744073709551615 134889774 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 14251 13907 218 433 0 13816 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 59600 [startup+12.7103 s] /proc/loadavg: 1.09 1.11 1.03 2/37 5797 /proc/meminfo: memFree=416020/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=55788 CPUtime=8.4 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 17327 0 0 0 833 7 0 0 25 0 1 0 1335426 57126912 13715 1283457024 134512640 136285277 4294138144 18446744073709551615 134931465 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 13947 13715 234 433 0 13512 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 58384 [startup+25.5046 s] /proc/loadavg: 1.08 1.10 1.03 2/37 5798 /proc/meminfo: memFree=414656/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=57768 CPUtime=21.19 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 17801 0 0 0 2111 8 0 0 25 0 1 0 1335426 59154432 14189 1283457024 134512640 136285277 4294138144 18446744073709551615 134966988 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 14442 14189 234 433 0 14007 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 60364 [startup+51.1113 s] /proc/loadavg: 1.05 1.09 1.03 2/36 5799 /proc/meminfo: memFree=366312/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=110412 CPUtime=46.78 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 31183 0 0 0 4665 13 0 0 25 0 1 0 1335426 113061888 27361 1283457024 134512640 136285277 4294138144 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 27603 27361 234 433 0 27168 0 Current children cumulated CPU time (s) 51.06 Current children cumulated vsize (KiB) 113008 [startup+102.304 s] /proc/loadavg: 1.02 1.08 1.02 2/35 5799 /proc/meminfo: memFree=284480/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=187880 CPUtime=97.9 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 50523 0 0 0 9769 21 0 0 25 0 1 0 1335426 192389120 46701 1283457024 134512640 136285277 4294138144 18446744073709551615 134723327 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 46970 46701 234 433 0 46535 0 Current children cumulated CPU time (s) 102.18 Current children cumulated vsize (KiB) 190476 [startup+162.31 s] /proc/loadavg: 1.00 1.06 1.02 2/35 5799 /proc/meminfo: memFree=246908/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=229536 CPUtime=157.84 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 60937 0 0 0 15762 22 0 0 25 0 1 0 1335426 235044864 57115 1283457024 134512640 136285277 4294138144 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 57384 57115 234 433 0 56949 0 Current children cumulated CPU time (s) 162.12 Current children cumulated vsize (KiB) 232132 [startup+222.306 s] /proc/loadavg: 1.00 1.05 1.01 2/35 5799 /proc/meminfo: memFree=227936/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=244404 CPUtime=217.79 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 64628 0 0 0 21756 23 0 0 25 0 1 0 1335426 250269696 60806 1283457024 134512640 136285277 4294138144 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 61101 60806 234 433 0 60666 0 Current children cumulated CPU time (s) 222.07 Current children cumulated vsize (KiB) 247000 [startup+282.312 s] /proc/loadavg: 1.00 1.04 1.01 2/35 5799 /proc/meminfo: memFree=184660/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=287732 CPUtime=277.76 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 75434 0 0 0 27750 26 0 0 25 0 1 0 1335426 294637568 71612 1283457024 134512640 136285277 4294138144 18446744073709551615 134985135 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 71933 71612 234 433 0 71498 0 Current children cumulated CPU time (s) 282.04 Current children cumulated vsize (KiB) 290328 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.304 s] /proc/loadavg: 1.00 1.03 1.01 2/35 5799 /proc/meminfo: memFree=184660/1048576 swapFree=0/0 [pid=5781] ppid=5780 vsize=2596 CPUtime=4.28 /proc/5781/stat : 5781 (aspcud-trendy-1) S 5780 5781 1511 34817 1511 4202496 624 38037 0 0 0 0 414 14 18 0 1 0 1335425 2658304 299 1283457024 134512640 135304128 4286751312 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/5781/statm: 649 299 251 194 0 36 0 [pid=5793] ppid=5781 vsize=287732 CPUtime=285.74 /proc/5793/stat : 5793 (clasp) R 5781 5781 1511 34817 1511 4202496 75437 0 0 0 28548 26 0 0 25 0 1 0 1335426 294637568 71615 1283457024 134512640 136285277 4294138144 18446744073709551615 134623651 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/5793/statm: 71933 71615 234 433 0 71498 0 Current children cumulated CPU time (s) 290.02 Current children cumulated vsize (KiB) 290328 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.344 CPU time (s): 290.078 CPU user time (s): 289.646 CPU system time (s): 0.432027 CPU usage (%): 99.9083 Max. virtual memory (cumulated for all children) (KiB): 290328 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.646 system time used= 0.432027 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 117822 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= 2920 involuntary context switches= 5777 runsolver used 0 second user time and 0 second system time The end