[ https://issues.apache.org/jira/browse/DRILL-4338?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15224552#comment-15224552 ]
Sudheesh Katkam commented on DRILL-4338: ---------------------------------------- Does not say there is a deadlock; jstack is failing while trying to detect deadlocks. Was the issue consistently reproducible in 1.6? Again, to clarify, issuing a Ctrl - C is almost like killing the program in this case. > Concurrent query remains in CANCELLATION_REQUESTED state > --------------------------------------------------------- > > Key: DRILL-4338 > URL: https://issues.apache.org/jira/browse/DRILL-4338 > Project: Apache Drill > Issue Type: Bug > Components: Execution - Flow > Affects Versions: 1.4.0 > Environment: 4 node cluster CentOS > Reporter: Khurram Faraaz > Attachments: ConcurrencyTest.java, > query_In_cancellation_requested_state.png > > > Execute a query concurrently through a Java program and while the java > program is under execution (executing SQL queries concurrently) issue Ctrl-C > on the prompt where the java program was being executed. > Here are two observations, > (1) There is an Exception in drillbit.log. > (2) Once Ctrl-C was issued to the java program, queries that were under > execution at that point of time, move from FAILED state to > CANCELLATION_REQUESTED state, they do not end up in CANCELED state. Ideally > that last state of these queries should be CANCELED state and not > CANCELLATION_REQUESTED. > Snippet from drillbit.log > {noformat} > 2016-02-02 06:21:21,903 [294fb51d-8a4c-c099-dc90-97434056e3d7:frag:0:0] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested > AWAITING_ALLOCATION --> RUNNING > 2016-02-02 06:21:21,903 [294fb51d-8a4c-c099-dc90-97434056e3d7:frag:0:0] INFO > o.a.d.e.w.f.FragmentStatusReporter - > 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State to report: RUNNING > 2016-02-02 06:21:48,560 [UserServer-1] ERROR > o.a.d.exec.rpc.RpcExceptionHandler - Exception in RPC communication. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client). > Closing connection. > java.io.IOException: syscall:read(...)() failed: Connection reset by peer > 2016-02-02 06:21:48,562 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested RUNNING --> > FAILED > 2016-02-02 06:21:48,562 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested RUNNING --> > FAILED > 2016-02-02 06:21:48,562 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested RUNNING --> > FAILED > 2016-02-02 06:21:48,563 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested RUNNING --> > FAILED > 2016-02-02 06:21:48,573 [CONTROL-rpc-event-queue] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested FAILED --> > CANCELLATION_REQUESTED > 2016-02-02 06:21:48,573 [CONTROL-rpc-event-queue] WARN > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-f424-6adc-d668-1659e4353698:0:0: Ignoring unexpected state > transition FAILED --> CANCELLATION_REQUESTED > 2016-02-02 06:21:48,580 [CONTROL-rpc-event-queue] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested FAILED --> > CANCELLATION_REQUESTED > 2016-02-02 06:21:48,580 [CONTROL-rpc-event-queue] WARN > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: Ignoring unexpected state > transition FAILED --> CANCELLATION_REQUESTED > 2016-02-02 06:21:48,588 [CONTROL-rpc-event-queue] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested FAILED --> > CANCELLATION_REQUESTED > 2016-02-02 06:21:48,588 [CONTROL-rpc-event-queue] WARN > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: Ignoring unexpected state > transition FAILED --> CANCELLATION_REQUESTED > 2016-02-02 06:21:48,596 [CONTROL-rpc-event-queue] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested FAILED --> > CANCELLATION_REQUESTED > 2016-02-02 06:21:48,596 [CONTROL-rpc-event-queue] WARN > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: Ignoring unexpected state > transition FAILED --> CANCELLATION_REQUESTED > 2016-02-02 06:21:48,597 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,599 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > 2016-02-02 06:21:48,600 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,600 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > 2016-02-02 06:21:48,601 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,601 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > 2016-02-02 06:21:48,601 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,601 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > 2016-02-02 06:21:48,602 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,602 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > 2016-02-02 06:21:48,602 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,603 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > 2016-02-02 06:21:48,603 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,603 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > 2016-02-02 06:21:48,603 [UserServer-1] INFO > o.a.d.e.w.fragment.FragmentExecutor - > 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested FAILED --> > FAILED > 2016-02-02 06:21:48,604 [UserServer-1] WARN > o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel. > Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client) > io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one > message. > at > io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) > ~[netty-codec-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) > [netty-transport-4.0.27.Final.jar:4.0.27.Final] > at > io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) > [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na] > at > io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) > [netty-common-4.0.27.Final.jar:4.0.27.Final] > at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65] > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)