Subject Jaybird driver not returning from simple update.
Author scott_fedelta
I am having a problem with not getting back data from
jaybird/firebirdsql on rare occasions. The following is part of a
thread dump when this is occuring:

"(JSK) Mux request dispatch" daemon prio=5 tid=0x02f59e38 nid=0xa80
runnable [3e3e000..3e3fd8c]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at org.firebirdsql.gds.XdrInputStream.read
(XdrInputStream.java:158)
at org.firebirdsql.gds.XdrInputStream.readInt
(XdrInputStream.java:121)
at org.firebirdsql.jgds.GDS_Impl.nextOperation
(GDS_Impl.java:1798)
at org.firebirdsql.jgds.GDS_Impl.isc_dsql_execute2
(GDS_Impl.java:908)
- locked <0x11e46e88> (a
org.firebirdsql.jgds.isc_db_handle_impl)
at org.firebirdsql.jca.FBManagedConnection.executeStatement
(FBManagedConnection.java:793)
at org.firebirdsql.jdbc.AbstractConnection.executeStatement
(AbstractConnection.java:946)
at
org.firebirdsql.jdbc.AbstractPreparedStatement.internalExecute
(AbstractPreparedStatement.java:499)
- locked <0x13a22280> (a
org.firebirdsql.jdbc.FBPreparedStatement)
at
org.firebirdsql.jdbc.AbstractPreparedStatement.executeUpdate
(AbstractPreparedStatement.java:144)
- locked <0x13a22280> (a
org.firebirdsql.jdbc.FBPreparedStatement)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate
(DelegatingPreparedStatement.java:101)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate
(DelegatingPreparedStatement.java:101)
at net.sf.hibernate.impl.NonBatchingBatcher.addToBatch
(NonBatchingBatcher.java:22)
at net.sf.hibernate.persister.EntityPersister.insert
(EntityPersister.java:462)
at net.sf.hibernate.persister.EntityPersister.insert
(EntityPersister.java:436)
at net.sf.hibernate.impl.ScheduledInsertion.execute
(ScheduledInsertion.java:37)
at net.sf.hibernate.impl.SessionImpl.execute
(SessionImpl.java:2449)
at net.sf.hibernate.impl.SessionImpl.executeAll
(SessionImpl.java:2435)
at net.sf.hibernate.impl.SessionImpl.execute
(SessionImpl.java:2392)
at net.sf.hibernate.impl.SessionImpl.flush
(SessionImpl.java:2261)
at net.sf.hibernate.transaction.JDBCTransaction.commit
(JDBCTransaction.java:61)
at
au.com.afgsoftware.pos.orders.server.table.TableManager.loadNewTable
(TableManager.java:1726)
at
au.com.afgsoftware.pos.orders.server.table.TableManager.getNewOrder
(TableManager.java:1118)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown
Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at net.jini.jeri.BasicInvocationDispatcher.invoke
(BasicInvocationDispatcher.java:1137)
at net.jini.jeri.BasicInvocationDispatcher.dispatch
(BasicInvocationDispatcher.java:621)
at com.sun.jini.jeri.internal.runtime.ObjectTable$6.run
(ObjectTable.java:606)
at net.jini.export.ServerContext.doWithServerContext
(ServerContext.java:116)
at
com.sun.jini.jeri.internal.runtime.ObjectTable$Target.dispatch0
(ObjectTable.java:604)
at
com.sun.jini.jeri.internal.runtime.ObjectTable$Target.access$700
(ObjectTable.java:225)
at com.sun.jini.jeri.internal.runtime.ObjectTable$5.run
(ObjectTable.java:579)
at com.sun.jini.start.AggregatePolicyProvider$6.run
(AggregatePolicyProvider.java:540)
at java.security.AccessController.doPrivileged(Native Method)
at
com.sun.jini.jeri.internal.runtime.ObjectTable$Target.dispatch
(ObjectTable.java:576)
at
com.sun.jini.jeri.internal.runtime.ObjectTable$Target.dispatch
(ObjectTable.java:553)
at com.sun.jini.jeri.internal.runtime.ObjectTable$RD.dispatch
(ObjectTable.java:780)
at
net.jini.jeri.connection.ServerConnectionManager$Dispatcher.dispatch
(ServerConnectionManager.java:161)
at com.sun.jini.jeri.internal.mux.MuxServer$2.run
(MuxServer.java:250)
at com.sun.jini.start.AggregatePolicyProvider$5.run
(AggregatePolicyProvider.java:526)
at java.security.AccessController.doPrivileged(Native Method)
at com.sun.jini.jeri.internal.mux.MuxServer$1.run
(MuxServer.java:247)
at com.sun.jini.thread.ThreadPool$Worker.run
(ThreadPool.java:149)
at java.lang.Thread.run(Unknown Source)


The loadNewTable() afgsoftware line simply saves a small object via
session.save() inside a hibernate2 session transaction. From the
logs you can see that it generates an insert stmt on the database
which Firebird (after locking for write) seems to be waiting for a
return from. Our full dump shows no deadlocks and nothing waiting
for a monitor (We visually analyzed and ran through a Thread Dump
Analyzer to confirm). The thread in question is runnable (no java
monitor deadlock) and just seems like it is waiting for a reply from
the database after execution of the sql statement via a socket read.

Is there something which would cause firebird to not return from an
insert, or take a long time to return, i.e db load? Concurrency prob?
Etc. We don't seem to get a return from this insert and consequently
our application hangs (hence the thread dump). The occurrence of the
problem is random, but usually confined to times when the database is
particularly under load during busy trade. This is normally a
transaction that would take much less than 1 second and it's being
left for > 5 minutes without return (In one case 45 mins). Restarting
our server (which reconnects to the database) fixes up the issue -
there is no need to restart the Firebird server itself. We know that
that a couple of very simple update queries on the same table fail to
return a result when this state is reached but read queries on other
tables in the database respond. I am not yet sure about updates on
tables other than the one in question. We cannot readily reproduce
this issue so we are just building information when we hit the issue
in production (far from a desired approach).

We are using:

JAYBIRD 1.5.6
Hibernate 2.1.8
Firebird 1.5.2
Java 1.4.2_06

Windows XP Service Pack 3, Core 2 duo 2.8GHz. Default CPU affinity
settings are in effect.

If there is any guidance as to what this issue may relate to I would
greatly appreciate it.

Kind regards,

Scott