Deadlock in JDBC Virtuoso connection pool

[jeremiehuchet]

When I use VirtuosoConnectionPoolDataSource to manage connections in a multithreaded environment I observe deadlocks.

I pushed a sample project: https://github.com/kops/jena-virtuoso-example

Here is a partial ThreadDump

2014-10-06 23:58:10
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.0-b56 mixed mode):

"Virtuoso Property Checker" daemon prio=10 tid=0x00007fd5c8015800 nid=0x2d49 waiting on condition [0x00007fd61cc0a000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at virtuoso.jdbc4.VirtuosoPoolManager$2.run(VirtuosoPoolManager.java:45)

   Locked ownable synchronizers:
    - None

"Virtuoso Pool Checker" daemon prio=10 tid=0x00007fd5c8009800 nid=0x2d48 waiting for monitor entry [0x00007fd61cd0b000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache.checkPool(VirtuosoConnectionPoolDataSource.java:514)
    - waiting to lock <0x000000078782a158> (a virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache.access$100(VirtuosoConnectionPoolDataSource.java:345)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource.checkPool(VirtuosoConnectionPoolDataSource.java:66)
    at virtuoso.jdbc4.VirtuosoPoolManager$1.run(VirtuosoPoolManager.java:30)

   Locked ownable synchronizers:
    - None

"pool-1-thread-2" prio=10 tid=0x00007fd628163800 nid=0x2d47 waiting for monitor entry [0x00007fd61ce0c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at virtuoso.jdbc4.VirtuosoPreparedStatement.sendQuery(VirtuosoPreparedStatement.java:68)
    - waiting to lock <0x000000078782a648> (a virtuoso.jdbc4.VirtuosoConnection)
    at virtuoso.jdbc4.VirtuosoPreparedStatement.execute(VirtuosoPreparedStatement.java:108)
    at virtuoso.jdbc4.VirtuosoConnection.isConnectionLost(VirtuosoConnection.java:179)
    at virtuoso.jdbc4.VirtuosoPooledConnection.isConnectionLost(VirtuosoPooledConnection.java:148)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache.lookup(VirtuosoConnectionPoolDataSource.java:425)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache.getPooledConnection(VirtuosoConnectionPoolDataSource.java:452)
    - locked <0x000000078782a158> (a virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache.access$800(VirtuosoConnectionPoolDataSource.java:345)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource.getPooledConnection(VirtuosoConnectionPoolDataSource.java:198)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource.getPooledConnection(VirtuosoConnectionPoolDataSource.java:169)
    at virtuoso.jena.driver.VirtGraph.<init>(Unknown Source)
    at fr.dudie.jena.example.VirtuosoConnectionPoolDeadLockExample$TripleInsertion.run(VirtuosoConnectionPoolDeadLockExample.java:103)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - <0x0000000787c7e968> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"pool-1-thread-1" prio=10 tid=0x00007fd628161000 nid=0x2d46 waiting for monitor entry [0x00007fd61cf0d000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache.reusePooledConnection(VirtuosoConnectionPoolDataSource.java:388)
    - waiting to lock <0x000000078782a158> (a virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource$ConnCache.access$600(VirtuosoConnectionPoolDataSource.java:345)
    at virtuoso.jdbc4.VirtuosoConnectionPoolDataSource.connectionClosed(VirtuosoConnectionPoolDataSource.java:117)
    at virtuoso.jdbc4.VirtuosoPooledConnection.sendCloseEvent(VirtuosoPooledConnection.java:170)
    at virtuoso.jdbc4.ConnectionWrapper.close(ConnectionWrapper.java:56)
    - locked <0x00000007d7297b18> (a virtuoso.jdbc4.ConnectionWrapper)
    at virtuoso.jena.driver.VirtGraph.close(Unknown Source)
    at com.hp.hpl.jena.rdf.model.impl.ModelCom.close(ModelCom.java:1420)
    at fr.dudie.jena.example.VirtuosoConnectionPoolDeadLockExample$TripleInsertion.run(VirtuosoConnectionPoolDeadLockExample.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - <0x0000000787cc16d0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"Finalizer" daemon prio=10 tid=0x00007fd628135000 nid=0x2d35 runnable [0x00007fd61e92a000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:152)
    at java.net.SocketInputStream.read(SocketInputStream.java:122)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
    - locked <0x000000078782a840> (a virtuoso.jdbc4.VirtuosoInputStream)
    at virtuoso.jdbc4.VirtuosoInputStream.read(VirtuosoInputStream.java:14)
    at virtuoso.jdbc4.VirtuosoInputStream.read_object(VirtuosoInputStream.java:50)
    at virtuoso.jdbc4.VirtuosoConnection.read_request(VirtuosoConnection.java:481)
    at virtuoso.jdbc4.VirtuosoFuture.nextResult(VirtuosoFuture.java:55)
    at virtuoso.jdbc4.VirtuosoPreparedStatement.close(VirtuosoPreparedStatement.java:191)
    - locked <0x000000078782a648> (a virtuoso.jdbc4.VirtuosoConnection)
    at virtuoso.jdbc4.VirtuosoStatement.finalize(VirtuosoStatement.java:152)
    at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
    at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:101)
    at java.lang.ref.Finalizer.access$100(Finalizer.java:32)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:190)

   Locked ownable synchronizers:
    - None

"main" prio=10 tid=0x00007fd628008000 nid=0x2d2e waiting on condition [0x00007fd62e47e000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0000000787cdf680> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
    at java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1468)
    at fr.dudie.jena.example.VirtuosoConnectionPoolDeadLockExample.run(VirtuosoConnectionPoolDeadLockExample.java:82)
    at fr.dudie.jena.example.Launcher.main(Launcher.java:50)

   Locked ownable synchronizers:
    - None

[smalinin]

I could recreate the issue above, it looks like a bug in PreparedStatement caching, I am working for fix it.

[smalinin]

The issue was fixed, it was in PrepraredStatement.close() method. Also:

• removed deprecated PrepredStatement cache from ConnectionWrapper
• ConnectionPool cache was updated for more optimal using of locks

The update will be committed in Git soon.

[HughWilliams]

Hi Can you confirm if this problem is still an issue for you particularly with the latest Virtuoso 7.2 release where a fix is available ?