query timeout not working

[Jasper Koehorst]

Hello,

I have set the query timeout on 5min like this:

# The timeout values specified in the property file should be a positive integer followed by either letter 'h' (for

# hours), letter 'm' (for minutes), letter 's' (for seconds), or letters 'ms' (for milliseconds).
# Examples: '1h' for 1 hour, '5m' for 5 minutes, '90s' for 90 seconds, '500ms' for 500 milliseconds.
#

query.timeout = 5m

Now I ran a heavy query to do some performance testing. However after half an hour it is still running!

How does this timeout works?

I do however have a list of event executer terminated:

Aug 05, 2014 7:02:49 AM io.netty.util.internal.logging.Slf4JLogger warn

WARNING: Failed to submit an exceptionCaught() event.
java.util.concurrent.RejectedExecutionException: event executor terminated
 at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:735)
 at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:312)
 at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:718)
 at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:251)
 at io.netty.channel.ChannelHandlerAdapter.exceptionCaught(ChannelHandlerAdapter.java:88)
 at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:270)
 at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:248)
 at io.netty.channel.ChannelInboundHandlerAdapter.exceptionCaught(ChannelInboundHandlerAdapter.java:131)
 at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:270)
 at io.netty.channel.AbstractChannelHandlerContext.notifyHandlerException(AbstractChannelHandlerContext.java:767)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:184)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.CombinedChannelDuplexHandler.channelUnregistered(CombinedChannelDuplexHandler.java:123)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.DefaultChannelPipeline.fireChannelUnregistered(DefaultChannelPipeline.java:738)
 at io.netty.channel.AbstractChannel$AbstractUnsafe$6.run(AbstractChannel.java:607)
 at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:370)
 at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:353)
 at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
 at java.lang.Thread.run(Thread.java:744)

Aug 05, 2014 7:02:49 AM io.netty.util.internal.logging.Slf4JLogger warn

WARNING: The exceptionCaught() event that was failed to submit was:
java.util.concurrent.RejectedExecutionException: event executor terminated
 at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:735)
 at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:312)
 at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:718)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:170)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(AbstractChannelHandlerContext.java:182)
 at io.netty.channel.AbstractChannelHandlerContext.fireChannelUnregistered(AbstractChannelHandlerContext.java:168)
 at io.netty.channel.ChannelInboundHandlerAdapter.channelUnregistered(ChannelInboundHandlerAdapter.java:53)
 at io.netty.channel.AbstractChannelHandlerContext.invokeChannelUnregistered(Abs

I also tried to list the queries 

/stardog/stardog/stardog-2.2/bin/stardog-admin --server snarl://127.0.0.1:4567 query list -u xxxxx -p xxx

or kill the query as I think there was only one running I tried 1.

/stardog/stardog/stardog-2.2/bin/stardog-admin --server snarl://127.0.0.1:4567 query kill 1 -u xxx -p xxxx

only they use 20% cpu for a second then drop to 0% and just sit there doing nothing....  as mentioned in a previous post.

 1  [|||||||||||||||||||||||||||||||||97.4%]   5  [|||||||||||||||||||||||||||||||||97.4%]     9  [|||||||||||||||||||||||||||||||||98.0%]   13 [|||||||||||||||||||||||||||||||||98.0%]
 2  [||||||||||||||||||||||||||||||||100.0%]   6  [|||||||||||||||||||||||||||||||||96.7%]     10 [|||||||||||||||||||||||||||||||||97.4%]   14 [                                  0.0%]
 3  [|||||||||||||||||||||||||||||||||96.7%]   7  [|||||||||||||||||||||||||||||||  78.6%]     11 [||||||||||||                     29.4%]   15 [|||||||||||||||||||||||||||||||||97.4%]
 4  [|||||||||||||||||||||||||||||||||96.7%]   8  [|||||||||||||||||||||||||||      68.0%]     12 [|||||||||                        21.6%]   16 [|||||||||||||||||||||||||||||||||97.4%]
 Mem[||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||41202/120866MB]     Tasks: 106; 14 running
 Swp[|                                                                        166/65523MB]     Load average: 11.96 12.23 12.31  
 Tasks: 106; 14 running                                                                        Uptime: 22:17:56

  IO_RBYTES   IO_WBYTES   PID USER      PRI  NI  VIRT   RES   SHR S CPU% MEM%   TIME+  Command
          0           0  8569 xxx      20   0 51.4G 44.2G 7980M S 1261 37.5 66h31:10 java -Xms4g -Xmx16g -XX:MaxDirectMemorySize=100g -Dstardog.install.location=/stardog/stardog/stardog-2   << QUERY
          0           0  3760 xxx      20   0 18.6G  148M 16824 S  0.0  0.1  0:02.62 java -Xms4g -Xmx16g -XX:MaxDirectMemorySize=100g -Dstardog.install.location=/stardog/stardog/stardog-2   << KILL COMMAND

After a fair few hours the query finally finished. While running less complicated queries I pulled up the query list and saw this:

+----------+----------+-------+--------------+--------------+
| Query ID | Database | User  | Elapsed time |   Timeout    |
+----------+----------+-------+--------------+--------------+
| 409      | ncbi     | admin | 01:08:32.435 | 00:05:00.000 |
| 410      | ncbi     | admin | 01:08:26.843 | 00:05:00.000 |
+----------+----------+-------+--------------+--------------+

Thanks,

Jasper

[Mike Grove]

On Tue, Aug 5, 2014 at 1:34 AM, Jasper Koehorst <jasperk...@gmail.com> wrote:

Hello,

I have set the query timeout on 5min like this:

# The timeout values specified in the property file should be a positive integer followed by either letter 'h' (for

# hours), letter 'm' (for minutes), letter 's' (for seconds), or letters 'ms' (for milliseconds). 

# Examples: '1h' for 1 hour, '5m' for 5 minutes, '90s' for 90 seconds, '500ms' for 500 milliseconds.

# 

query.timeout = 5m

Now I ran a heavy query to do some performance testing. However after half an hour it is still running!

How does this timeout works?

Checks are made periodically during evaluation to see if the runtime is past the timeout.  It's a tough balance to avoid doing too many checks and as a result, slowing down the actual evaluation.  If the query is not timing out, it's probably doing heavy computation in between checks.

Cheers,

Mike

 

Thanks,

Jasper

--
-- --
You received this message because you are subscribed to the C&P "Stardog" group.
To post to this group, send email to sta...@clarkparsia.com
To unsubscribe from this group, send email to
stardog+u...@clarkparsia.com
For more options, visit this group at
http://groups.google.com/a/clarkparsia.com/group/stardog?hl=en