Druid: deadlock found in DruidStatement

[zhaojiandong]

We found deadlock in DruidStatement and DruidConnection, this will cause exhaust connections.

Found one Java-level deadlock:
=============================
"DruidMeta@4e50ae56-ScheduledExecutor":
  waiting to lock monitor 0x00007fa5084802b8 (object 0x00000000d6389830, a java.lang.Object),
  which is held by "qtp1871838170-210"
"qtp1871838170-210":
  waiting to lock monitor 0x00007fa5084916b8 (object 0x00000000d603e4b8, a java.util.HashMap),
  which is held by "DruidMeta@4e50ae56-ScheduledExecutor"

Java stack information for the threads listed above:
===================================================
"DruidMeta@4e50ae56-ScheduledExecutor":
    at io.druid.sql.avatica.DruidStatement.close(DruidStatement.java:310)
    - waiting to lock <0x00000000d6389830> (a java.lang.Object)
    at io.druid.sql.avatica.DruidConnection.close(DruidConnection.java:150)
    - locked <0x00000000d603e4b8> (a java.util.HashMap)
    at io.druid.sql.avatica.DruidMeta.closeConnection(DruidMeta.java:120)
    at io.druid.sql.avatica.DruidMeta.lambda$getDruidConnection$0(DruidMeta.java:588)
    at io.druid.sql.avatica.DruidMeta$$Lambda$90/10531789.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
"qtp1871838170-210":
    at io.druid.sql.avatica.DruidConnection.lambda$createStatement$0(DruidConnection.java:107)
    - waiting to lock <0x00000000d603e4b8> (a java.util.HashMap)
    at io.druid.sql.avatica.DruidConnection$$Lambda$91/1439788572.run(Unknown Source)
    at io.druid.sql.avatica.DruidStatement.close(DruidStatement.java:348)
    - locked <0x00000000d6389830> (a java.lang.Object)
    at io.druid.sql.avatica.DruidStatement.execute(DruidStatement.java:213)
    - locked <0x00000000d6389830> (a java.lang.Object)
    at io.druid.sql.avatica.DruidMeta.prepareAndExecute(DruidMeta.java:187)
    at org.apache.calcite.avatica.remote.LocalService.apply(LocalService.java:206)
    at org.apache.calcite.avatica.remote.Service$PrepareAndExecuteRequest.accept(Service.java:928)
    at org.apache.calcite.avatica.remote.Service$PrepareAndExecuteRequest.accept(Service.java:880)
    at org.apache.calcite.avatica.remote.AbstractHandler.apply(AbstractHandler.java:94)
    at org.apache.calcite.avatica.remote.JsonHandler.apply(JsonHandler.java:52)
    at org.apache.calcite.avatica.server.AvaticaJsonHandler.handle(AvaticaJsonHandler.java:130)
    at io.druid.sql.avatica.DruidAvaticaHandler.handle(DruidAvaticaHandler.java:60)
    at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
    at org.eclipse.jetty.server.Server.handle(Server.java:534)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:748)

Found one Java-level deadlock:
=============================
"qtp1871838170-283":
  waiting to lock monitor 0x00007fa50b53c918 (object 0x00000007712471d8, a java.lang.Object),
  which is held by "qtp1871838170-199"
"qtp1871838170-199":
  waiting to lock monitor 0x00007fa508d0ae68 (object 0x00000007766ce418, a java.util.HashMap),
  which is held by "qtp1871838170-283"

Java stack information for the threads listed above:
===================================================
"qtp1871838170-283": 
    at io.druid.sql.avatica.DruidStatement.close(DruidStatement.java:310)
    - waiting to lock <0x00000007712471d8> (a java.lang.Object)
    at io.druid.sql.avatica.DruidConnection.close(DruidConnection.java:150)
    - locked <0x00000007766ce418> (a java.util.HashMap)
    at io.druid.sql.avatica.DruidMeta.closeConnection(DruidMeta.java:120)
    at org.apache.calcite.avatica.remote.LocalService.apply(LocalService.java:292)
    at org.apache.calcite.avatica.remote.Service$CloseConnectionRequest.accept(Service.java:1907)
    at org.apache.calcite.avatica.remote.Service$CloseConnectionRequest.accept(Service.java:1890)
    at org.apache.calcite.avatica.remote.AbstractHandler.apply(AbstractHandler.java:94)
    at org.apache.calcite.avatica.remote.JsonHandler.apply(JsonHandler.java:52)
    at org.apache.calcite.avatica.server.AvaticaJsonHandler.handle(AvaticaJsonHandler.java:130)
    at io.druid.sql.avatica.DruidAvaticaHandler.handle(DruidAvaticaHandler.java:60)
    at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
    at org.eclipse.jetty.server.Server.handle(Server.java:534)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:748)
"qtp1871838170-199":  
    at io.druid.sql.avatica.DruidConnection.lambda$createStatement$0(DruidConnection.java:107)
    - waiting to lock <0x00000007766ce418> (a java.util.HashMap)
    at io.druid.sql.avatica.DruidConnection$$Lambda$91/1439788572.run(Unknown Source)
    at io.druid.sql.avatica.DruidStatement.close(DruidStatement.java:348)
    - locked <0x00000007712471d8> (a java.lang.Object)
    at io.druid.sql.avatica.DruidStatement.nextFrame(DruidStatement.java:290)
    - locked <0x00000007712471d8> (a java.lang.Object)
    at io.druid.sql.avatica.DruidMeta.prepareAndExecute(DruidMeta.java:188)
    at org.apache.calcite.avatica.remote.LocalService.apply(LocalService.java:206)
    at org.apache.calcite.avatica.remote.Service$PrepareAndExecuteRequest.accept(Service.java:928)
    at org.apache.calcite.avatica.remote.Service$PrepareAndExecuteRequest.accept(Service.java:880)
    at org.apache.calcite.avatica.remote.AbstractHandler.apply(AbstractHandler.java:94)
    at org.apache.calcite.avatica.remote.JsonHandler.apply(JsonHandler.java:52)
    at org.apache.calcite.avatica.server.AvaticaJsonHandler.handle(AvaticaJsonHandler.java:130)
    at io.druid.sql.avatica.DruidAvaticaHandler.handle(DruidAvaticaHandler.java:60)
    at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
    at org.eclipse.jetty.server.Server.handle(Server.java:534)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
    at java.lang.Thread.run(Thread.java:748)

[gianm]

Hi @zhaojiandong - what version was this seen on?

[zhaojiandong]

Hi @zhaojiandong - what version was this seen on?

Our version is 0.12.0, but I've found that the latest version is still possible.
I'll try to fix it
@gianm