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/201108311143/aspcud-1.5/ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/ca8f656c-db9e-11df-b9cf-00163e3d3b7c.cudf.dudf-real.result -sum(installedsize) 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.08 1.07 1.01 5/34 817 /proc/meminfo: memFree=667712/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2584 CPUtime=0 /proc/816/stat : 816 (aspcud-1.5) R 815 816 19908 34817 19908 4202496 366 0 0 0 0 0 0 0 25 0 1 0 67432157 2646016 279 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/816/statm: 646 279 234 194 0 33 0 [pid=817] ppid=816 vsize=2584 CPUtime=0 /proc/817/stat : 817 (aspcud-1.5) R 816 816 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 67432157 2646016 45 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/817/statm: 646 45 0 194 0 33 0 [startup+0.116853 s] /proc/loadavg: 1.08 1.07 1.01 5/34 817 /proc/meminfo: memFree=667712/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=0.01 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 1521 0 0 0 0 0 1 25 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.204855 s] /proc/loadavg: 1.08 1.07 1.01 5/34 817 /proc/meminfo: memFree=667712/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=0.01 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 1521 0 0 0 0 0 1 25 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.304864 s] /proc/loadavg: 1.08 1.07 1.01 5/34 817 /proc/meminfo: memFree=667712/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=0.01 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 1521 0 0 0 0 0 1 25 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.704889 s] /proc/loadavg: 1.08 1.07 1.01 5/34 817 /proc/meminfo: memFree=667712/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=0.01 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 1521 0 0 0 0 0 1 25 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.51334 s] /proc/loadavg: 1.08 1.06 1.01 2/37 827 /proc/meminfo: memFree=626216/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=0.01 /proc/816/stat : 816 (aspcud-1.5) R 815 816 19908 34817 19908 4202496 581 1521 0 0 0 0 0 1 18 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=5844 CPUtime=0 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 1353 0 0 0 0 0 0 0 18 0 1 0 67432158 5984256 1139 1283457024 134512640 136285277 4294760912 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 1461 1139 177 433 0 1026 0 [pid=826] ppid=816 vsize=7592 CPUtime=0.23 /proc/826/stat : 826 (gringo) R 816 816 19908 34817 19908 4202496 1907 0 0 0 22 1 0 0 18 0 1 0 67432158 7774208 1402 1283457024 134512640 136933539 4287718288 18446744073709551615 134732276 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/826/statm: 1898 1402 253 592 0 1303 0 [pid=827] ppid=816 vsize=0 CPUtime=1.16 /proc/827/stat : 827 (cudf2lp) Z 816 816 19908 34817 19908 4202508 8942 0 0 0 108 8 0 0 25 0 1 0 67432158 0 0 1283457024 0 0 0 0 0 0 0 6 0 18446744071564254338 0 0 17 0 0 0 0 /proc/827/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.4 Current children cumulated vsize (KiB) 16028 [startup+3.11367 s] /proc/loadavg: 1.08 1.06 1.01 2/35 827 /proc/meminfo: memFree=640136/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=15332 CPUtime=1.3 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 4424 0 0 0 130 0 0 0 19 0 1 0 67432158 15699968 3622 1283457024 134512640 136285277 4294760912 18446744073709551615 134733720 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 3833 3622 234 433 0 3398 0 Current children cumulated CPU time (s) 3 Current children cumulated vsize (KiB) 17924 [startup+6.31434 s] /proc/loadavg: 1.08 1.06 1.01 2/35 827 /proc/meminfo: memFree=625256/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=32356 CPUtime=4.5 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 9039 0 0 0 446 4 0 0 25 0 1 0 67432158 33132544 7876 1283457024 134512640 136285277 4294760912 18446744073709551615 134650353 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 8089 7876 234 433 0 7654 0 Current children cumulated CPU time (s) 6.2 Current children cumulated vsize (KiB) 34948 [startup+12.7057 s] /proc/loadavg: 1.06 1.06 1.01 2/35 827 /proc/meminfo: memFree=577524/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=77032 CPUtime=10.88 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 20481 0 0 0 1076 12 0 0 25 0 1 0 67432158 78880768 18714 1283457024 134512640 136285277 4294760912 18446744073709551615 134955168 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 19258 18714 234 433 0 18823 0 Current children cumulated CPU time (s) 12.58 Current children cumulated vsize (KiB) 79624 [startup+25.5087 s] /proc/loadavg: 1.05 1.06 1.01 2/35 827 /proc/meminfo: memFree=577524/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=79272 CPUtime=23.68 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 21272 0 0 0 2356 12 0 0 25 0 1 0 67432158 81174528 19312 1283457024 134512640 136285277 4294760912 18446744073709551615 134650371 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 19818 19312 234 433 0 19383 0 Current children cumulated CPU time (s) 25.38 Current children cumulated vsize (KiB) 81864 [startup+51.111 s] /proc/loadavg: 1.19 1.09 1.02 2/42 861 /proc/meminfo: memFree=537852/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=97944 CPUtime=48.92 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 25667 0 0 0 4876 16 0 0 25 0 1 0 67432158 100294656 23707 1283457024 134512640 136285277 4294760912 18446744073709551615 134955177 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 24486 23707 234 433 0 24051 0 Current children cumulated CPU time (s) 50.62 Current children cumulated vsize (KiB) 100536 [startup+102.306 s] /proc/loadavg: 1.25 1.13 1.04 2/36 915 /proc/meminfo: memFree=535568/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=97944 CPUtime=99.91 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 25667 0 0 0 9971 20 0 0 25 0 1 0 67432158 100294656 23707 1283457024 134512640 136285277 4294760912 18446744073709551615 134639152 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 24486 23707 234 433 0 24051 0 Current children cumulated CPU time (s) 101.61 Current children cumulated vsize (KiB) 100536 [startup+162.313 s] /proc/loadavg: 1.16 1.12 1.04 2/37 918 /proc/meminfo: memFree=534808/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=99672 CPUtime=159.9 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 26081 0 0 0 15970 20 0 0 25 0 1 0 67432158 102064128 24121 1283457024 134512640 136285277 4294760912 18446744073709551615 134955188 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 24918 24121 234 433 0 24483 0 Current children cumulated CPU time (s) 161.6 Current children cumulated vsize (KiB) 102264 [startup+222.307 s] /proc/loadavg: 1.06 1.10 1.03 2/37 924 /proc/meminfo: memFree=534436/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=99488 CPUtime=219.84 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 28109 0 0 0 21961 23 0 0 25 0 1 0 67432158 101875712 24063 1283457024 134512640 136285277 4294760912 18446744073709551615 134966723 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 24872 24063 234 433 0 24437 0 Current children cumulated CPU time (s) 221.54 Current children cumulated vsize (KiB) 102080 [startup+282.31 s] /proc/loadavg: 1.02 1.08 1.02 2/36 926 /proc/meminfo: memFree=533708/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=100344 CPUtime=279.76 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 29059 0 0 0 27953 23 0 0 25 0 1 0 67432158 102752256 24277 1283457024 134512640 136285277 4294760912 18446744073709551615 134959557 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 25086 24277 234 433 0 24651 0 Current children cumulated CPU time (s) 281.46 Current children cumulated vsize (KiB) 102936 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.912 s] /proc/loadavg: 1.02 1.07 1.02 2/36 926 /proc/meminfo: memFree=534700/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=98552 CPUtime=288.36 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 29635 0 0 0 28812 24 0 0 25 0 1 0 67432158 100917248 23860 1283457024 134512640 136285277 4294760912 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 24638 23860 234 433 0 24203 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 101144 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.912 s] /proc/loadavg: 1.02 1.07 1.02 2/36 926 /proc/meminfo: memFree=534700/1048576 swapFree=0/0 [pid=816] ppid=815 vsize=2592 CPUtime=1.7 /proc/816/stat : 816 (aspcud-1.5) S 815 816 19908 34817 19908 4202496 581 15593 0 0 0 0 158 12 16 0 1 0 67432157 2654208 298 1283457024 134512640 135304128 4287285904 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/816/statm: 648 298 251 194 0 35 0 [pid=825] ppid=816 vsize=98552 CPUtime=288.36 /proc/825/stat : 825 (clasp) R 816 816 19908 34817 19908 4202496 29635 0 0 0 28812 24 0 0 25 0 1 0 67432158 100917248 23860 1283457024 134512640 136285277 4294760912 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/825/statm: 24638 23860 234 433 0 24203 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 101144 Child status: 0 Real time (s): 290.945 CPU time (s): 290.106 CPU user time (s): 289.714 CPU system time (s): 0.392024 CPU usage (%): 99.7115 Max. virtual memory (cumulated for all children) (KiB): 104512 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.714 system time used= 0.392024 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 49634 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= 673 involuntary context switches= 4724 runsolver used 0 second user time and 0 second system time The end