Deadlock in Oracle JDBC driver (9.2)

[andy.m...@gmail.com]

Hello All,

I would like to get some advise. We have Java application server
(Tomcat) that periodically (approximately every other day) experiences
Java-level deadlocks in JDBC code. We have full thread dumps. Please
look into the snapshot thread dump (below).

One thread of our code performs a lot of JDBC reads, which deep inside
obtain few low-level locks (first on oracle.jdbc.ttc7.TTC7Protocol,
then oracle.jdbc.driver.OracleConnection).

The same locks are being obtained IN REVERSE ORDER by another thread
(GC Finalizer) that is trying to garbage-collect a PreparedStatement
object that was created for the same connection.

I can see only one way of fixing this problem - patching our code that
releases prepared statements to get access to Oracle guts and try to
obtain an additional lock on TTC7Protocol (so that lock order will
correspond to the first thread). Oracle JDBC sources are not available,
so we have to disassemble them. There is no guarantee that this patch
will not introduce new deadlocks.

Will appreciate any advice,
Andy

Found one Java-level deadlock:
=============================

"Activity Processor group 2 number 1":
waiting to lock monitor 0x009889c4 (object 0x1ff96dd8, a
oracle.jdbc.driver.OracleConnection),
which is held by "Finalizer"

"Finalizer":
waiting to lock monitor 0x009888e4 (object 0x1ffa4d58, a
oracle.jdbc.ttc7.TTC7Protocol),
which is held by "Activity Processor group 2 number 1"

Java stack information for the threads listed above:
===================================================

"Activity Processor group 2 number 1":
at
oracle.jdbc.driver.OracleConnection.needLine(OracleConnection.java:2389)
(A) waiting to lock <0x1ff96dd8> (a
oracle.jdbc.driver.OracleConnection)
at
oracle.jdbc.ttc7.TTC7Protocol.lobRead(TTC7Protocol.java:2407)
(B) locked <0x1ffa4d58> (a oracle.jdbc.ttc7.TTC7Protocol)
at
oracle.sql.LobDBAccessImpl.getBytes(LobDBAccessImpl.java:242)
- locked <0x2001b4e0> (a oracle.sql.LobDBAccessImpl)
at oracle.sql.BLOB.getBytes(BLOB.java:340)
at oracle.sql.BLOB.getBytes(BLOB.java:205)
....

"Finalizer":

at oracle.jdbc.ttc7.TTC7Protocol.close(TTC7Protocol.java:667)
(B) waiting to lock <0x1ffa4d58> (a
oracle.jdbc.ttc7.TTC7Protocol)
at
oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:700)
- locked <0x29a26c38> (a
oracle.jdbc.driver.OraclePreparedStatement)
(A) locked <0x1ff96dd8> (a oracle.jdbc.driver.OracleConnection)
at
oracle.jdbc.driver.OraclePreparedStatement.exitImplicitCacheToClose(OraclePreparedStatement.java:354)
at
oracle.jdbc.driver.LRUStatementCache.purgeCacheEntry(LRUStatementCache.java:774)
at
oracle.jdbc.driver.LRUStatementCache.addToImplicitCache(LRUStatementCache.java:312)
at
oracle.jdbc.driver.OracleConnection.cacheImplicitStatement(OracleConnection.java:4477)
(A) locked <0x1ff96dd8> (a oracle.jdbc.driver.OracleConnection)
at
oracle.jdbc.driver.OraclePreparedStatement.privateClose(OraclePreparedStatement.java:458)
at
oracle.jdbc.driver.OraclePreparedStatement.close(OraclePreparedStatement.java:396)
- locked <0x29a26d20> (a
oracle.jdbc.driver.OraclePreparedStatement)
(A) locked <0x1ff96dd8> (a oracle.jdbc.driver.OracleConnection)
at
org.apache.ojb.broker.accesslayer.ResultSetAndStatement.close(Unknown
Source)
at
org.apache.ojb.broker.accesslayer.ResultSetAndStatement.finalize(Unknown
Source)
at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
at
java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160)

[Robert Klemme]

andy.m...@gmail.com wrote:
> Hello All,
>
> I would like to get some advise. We have Java application server
> (Tomcat) that periodically (approximately every other day) experiences
> Java-level deadlocks in JDBC code. We have full thread dumps. Please
> look into the snapshot thread dump (below).
>
> One thread of our code performs a lot of JDBC reads, which deep inside
> obtain few low-level locks (first on oracle.jdbc.ttc7.TTC7Protocol,
> then oracle.jdbc.driver.OracleConnection).
>
> The same locks are being obtained IN REVERSE ORDER by another thread
> (GC Finalizer) that is trying to garbage-collect a PreparedStatement
> object that was created for the same connection.
>
> I can see only one way of fixing this problem - patching our code that
> releases prepared statements to get access to Oracle guts and try to
> obtain an additional lock on TTC7Protocol (so that lock order will
> correspond to the first thread). Oracle JDBC sources are not available,
> so we have to disassemble them. There is no guarantee that this patch
> will not introduce new deadlocks.

I can see another potential solution: notice that the finalizer invokes
PS.close()? Your code probably does not invoke close() before it
releases the last reference to the PS. So the close has to be done in
the finalizer's thread which causes the behavior you see.

My solution to preventing this is to do it in finally blocks:

PS ps = conn.prepareStatement(sql);
// no code here that can throw!
try {
// use ps
}
finally {
ps.close();
}

Kind regards

robert

[andy.m...@gmail.com]

Thanks Robert ,

You right, that idea occured to me as well.

Unfortunately I am dealing with persistence framework that hides access
to PS.close(). Luckily its open source :-)

[Robert Klemme]

And you are sure you use the framework properly? This looks like such
an obvious bug that someone should have spotted it already. That is,
unless the software is alpha...

Regards

robert