BTM
  1. BTM
  2. BTM-59

Bitronix evicting/closing an in-use PreparedStatement from cache, causing a downstream failure

    Details

    • Type: Bug Bug
    • Status: Closed Closed
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 1.3.3
    • Fix Version/s: 2.0.0
    • Labels:
      None
    • Environment:
      Derby 10.5.3.0, Java 6
    • Number of attachments :
      2

      Description

      I have recently enabled the prepared statement cache and am now experiencing a failure that appears to be caused by the Bitronix LruEvictionListener evicting an in-use statement.

      Attached is a log file containing the failure. The log has been truncated for size, but I believe it contains enough required information. The thread of interest is named "Jetty-8".

      I reproduce some of the log here, containing only Jetty-8 interactions:

      09-12-11 13:35:08,718 [itronixTransactionManager] [Jetty-8 ] DEBUG - creating new thread context
      09-12-11 13:35:08,718 [itronixTransactionManager] [Jetty-8 ] DEBUG - changing current thread context to a ThreadContext with transaction null, default timeout 180s
      09-12-11 13:35:08,718 [ThreadContext ] [Jetty-8 ] DEBUG - changing default timeout of thread context to 300000s
      09-12-11 13:35:08,718 [itronixTransactionManager] [Jetty-8 ] DEBUG - beginning a new transaction
      09-12-11 13:35:08,718 [itronixTransactionManager] [Jetty-8 ] DEBUG - dumping 0 transaction context(s)
      09-12-11 13:35:08,718 [BitronixTransaction ] [Jetty-8 ] DEBUG - creating new transaction with GTRID [6E65746C642D31000001257C04D32E00000761]
      09-12-11 13:35:08,718 [TaskScheduler ] [Jetty-8 ] DEBUG - scheduling transaction timeout task on a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=NO_TRANSACTION, 0 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009) for Mon Dec 14 15:55:08 GMT+00:00 2009
      09-12-11 13:35:08,718 [TaskScheduler ] [Jetty-8 ] DEBUG - removing task by a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=NO_TRANSACTION, 0 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)
      09-12-11 13:35:08,718 [TaskScheduler ] [Jetty-8 ] DEBUG - scheduled a TransactionTimeoutTask on a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=NO_TRANSACTION, 0 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009) scheduled for Mon Dec 14 15:55:08 GMT+00:00 2009, total task(s) queued: 3
      09-12-11 13:35:08,718 [ThreadContext ] [Jetty-8 ] DEBUG - assigning <a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=NO_TRANSACTION, 0 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)> to <a ThreadContext with transaction null, default timeout 300000s>
      09-12-11 13:35:08,718 [BitronixTransaction ] [Jetty-8 ] DEBUG - changing transaction status to ACTIVE
      09-12-11 13:35:08,718 [TransactionLogAppender ] [Jetty-8 ] DEBUG - between 339595 and 339651, writing a Bitronix TransactionLogRecord with status=ACTIVE, recordLength=48, headerLength=28, time=1260506108718, sequenceNumber=1890, crc32=-286133363, gtrid=6E65746C642D31000001257C04D32E00000761, uniqueNames=
      09-12-11 13:35:08,718 [TransactionLogAppender ] [Jetty-8 ] DEBUG - disk journal appender now at position 339651
      09-12-11 13:35:08,718 [BitronixTransaction ] [Jetty-8 ] DEBUG - transaction status is changing from NO_TRANSACTION to ACTIVE - executing 0 listener(s)
      09-12-11 13:35:08,718 [itronixTransactionManager] [Jetty-8 ] DEBUG - begun new transaction at 1260506108718
      09-12-11 13:35:08,718 [ThreadContext ] [Jetty-8 ] DEBUG - changing default timeout of thread context to 1800s
      09-12-11 13:35:08,718 [BitronixTransaction ] [Jetty-8 ] DEBUG - registering synchronization org.hibernate.transaction.CacheSynchronization
      09-12-11 13:35:08,718 [BitronixTransaction ] [Jetty-8 ] DEBUG - registering synchronization org.hibernate.context.JTASessionContext$CleanupSynch@23bf3d
      09-12-11 13:35:08,718 [PoolingDataSource ] [Jetty-8 ] DEBUG - acquiring connection from a PoolingDataSource containing an XAPool of resource ziptie-ds with 3 connection(s) (2 still available)
      09-12-11 13:35:08,718 [XAPool ] [Jetty-8 ] DEBUG - trying to recycle a NOT_ACCESSIBLE connection of an XAPool of resource ziptie-ds with 3 connection(s) (2 still available)
      09-12-11 13:35:08,718 [XAPool ] [Jetty-8 ] DEBUG - current transaction GTRID is [6E65746C642D31000001257C04D32E00000761]
      09-12-11 13:35:08,718 [XAPool ] [Jetty-8 ] DEBUG - no NOT_ACCESSIBLE connection enlisted in this transaction
      09-12-11 13:35:08,718 [XAPool ] [Jetty-8 ] DEBUG - getting a IN_POOL connection from an XAPool of resource ziptie-ds with 3 connection(s) (2 still available)
      09-12-11 13:35:08,718 [XAPool ] [Jetty-8 ] DEBUG - waiting for IN_POOL connections count to be > 0, currently is 2
      09-12-11 13:35:08,718 [XAPool ] [Jetty-8 ] DEBUG - found IN_POOL connection a JdbcPooledConnection from datasource ziptie-ds in state IN_POOL wrapping org.apache.derby.client.ClientXAConnection40@15bf05f from an XAPool of resource ziptie-ds with 3 connection(s) (2 still available)
      09-12-11 13:35:08,718 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - getting connection handle from a JdbcPooledConnection from datasource ziptie-ds in state IN_POOL wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,718 [AbstractXAStatefulHolder ] [Jetty-8 ] DEBUG - notifying 2 stateChangeEventListener(s) about state changing from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource ziptie-ds in state IN_POOL wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,718 [AbstractXAStatefulHolder ] [Jetty-8 ] DEBUG - state changing from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource ziptie-ds in state IN_POOL wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,718 [AbstractXAStatefulHolder ] [Jetty-8 ] DEBUG - notifying 2 stateChangeEventListener(s) about state changed from IN_POOL to ACCESSIBLE in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,718 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - connection org.apache.derby.client.ClientXAConnection40@15bf05f was in state IN_POOL, testing it
      09-12-11 13:35:08,718 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - testing with query 'VALUES 1' connection of a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,718 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - successfully tested connection of a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,718 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - got connection handle from a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,718 [PoolingDataSource ] [Jetty-8 ] DEBUG - acquired connection from a PoolingDataSource containing an XAPool of resource ziptie-ds with 3 connection(s) (1 still available)
      09-12-11 13:35:08,718 [TransactionContextHelper ] [Jetty-8 ] DEBUG - enlisting a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f into a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=ACTIVE, 0 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)
      09-12-11 13:35:08,718 [TransactionContextHelper ] [Jetty-8 ] DEBUG - enlisting resource an XAResourceHolderState with uniqueName=ziptie-ds XAResource=org.apache.derby.client.net.NetXAResource@1826710 with XID null into a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=ACTIVE, 0 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)
      09-12-11 13:35:08,734 [AbstractXAResourceHolder ] [Jetty-8 ] DEBUG - setting default XAResourceHolderState [an XAResourceHolderState with uniqueName=ziptie-ds XAResource=org.apache.derby.client.net.NetXAResource@1826710 with XID null] on a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,734 [AbstractXAResourceHolder ] [Jetty-8 ] DEBUG - XAResourceHolderState previously unknown, adding it to the list
      09-12-11 13:35:08,734 [ResourceRegistrar ] [Jetty-8 ] DEBUG - XAResource org.apache.derby.client.net.NetXAResource@1826710 belongs to a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f that itself belongs to a PoolingDataSource containing an XAPool of resource ziptie-ds with 3 connection(s) (1 still available)
      09-12-11 13:35:08,734 [XAResourceManager ] [Jetty-8 ] DEBUG - creating new branch with a Bitronix XID [6E65746C642D31000001257C04D32E00000761 : 6E65746C642D31000001257C04D33E00000764]
      09-12-11 13:35:08,734 [XAResourceHolderState ] [Jetty-8 ] DEBUG - assigning <a Bitronix XID [6E65746C642D31000001257C04D32E00000761 : 6E65746C642D31000001257C04D33E00000764]> to <an XAResourceHolderState with uniqueName=ziptie-ds XAResource=org.apache.derby.client.net.NetXAResource@1826710 with XID null>
      09-12-11 13:35:08,734 [XAResourceHolderState ] [Jetty-8 ] DEBUG - starting an XAResourceHolderState with uniqueName=ziptie-ds XAResource=org.apache.derby.client.net.NetXAResource@1826710 with XID a Bitronix XID [6E65746C642D31000001257C04D32E00000761 : 6E65746C642D31000001257C04D33E00000764]
      09-12-11 13:35:08,734 [XAResourceManager ] [Jetty-8 ] DEBUG - started an XAResourceHolderState with uniqueName=ziptie-ds XAResource=org.apache.derby.client.net.NetXAResource@1826710 (started) with XID a Bitronix XID [6E65746C642D31000001257C04D32E00000761 : 6E65746C642D31000001257C04D33E00000764] with NOFLAGS
      09-12-11 13:35:08,734 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - statement cache lookup of <select this_.id as y0_, this_.execution_id as y1_, this_.device_id as y2_, this_.error as y3_, this_.grid_data as y4_, this_.start_time as y5_, this_.end_time as y6_ from tool_details this_ where this_.execution_id=?> in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f: null
      09-12-11 13:35:08,734 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - caching statement <select this_.id as y0_, this_.execution_id as y1_, this_.device_id as y2_, this_.error as y3_, this_.grid_data as y4_, this_.start_time as y5_, this_.end_time as y6_ from tool_details this_ where this_.execution_id=?> in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,734 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - closing evicted statement org.apache.derby.client.am.PreparedStatement40@122e6b5
      09-12-11 13:35:08,750 [TransactionContextHelper ] [Jetty-8 ] DEBUG - enlisting a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f into a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=ACTIVE, 1 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)
      09-12-11 13:35:08,843 [TransactionContextHelper ] [Jetty-8 ] DEBUG - avoiding re-enlistment of already enlisted but not ended resource an XAResourceHolderState with uniqueName=ziptie-ds XAResource=org.apache.derby.client.net.NetXAResource@1826710 (started) with XID a Bitronix XID [6E65746C642D31000001257C04D32E00000761 : 6E65746C642D31000001257C04D33E00000764]
      09-12-11 13:35:08,843 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - statement cache lookup of <select zdevicecor0_.device_id as device1_14_0_, zdevicecor0_.adapter_id as adapter2_14_0_, zdevicecor0_.hostname as hostname14_0_, zdevicecor0_.inode as inode14_0_, zdevicecor0_.ip_address as ip5_14_0_, zdevicecor0_.ip_high as ip6_14_0_, zdevicecor0_.ip_low as ip7_14_0_, zdevicecor0_.network as network14_0_ from device zdevicecor0_ where zdevicecor0_.device_id=?> in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f: null
      09-12-11 13:35:08,843 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - caching statement <select zdevicecor0_.device_id as device1_14_0_, zdevicecor0_.adapter_id as adapter2_14_0_, zdevicecor0_.hostname as hostname14_0_, zdevicecor0_.inode as inode14_0_, zdevicecor0_.ip_address as ip5_14_0_, zdevicecor0_.ip_high as ip6_14_0_, zdevicecor0_.ip_low as ip7_14_0_, zdevicecor0_.network as network14_0_ from device zdevicecor0_ where zdevicecor0_.device_id=?> in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:08,953 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - closing evicted statement org.apache.derby.client.am.PreparedStatement40@abc86c
      09-12-11 13:35:08,953 [bcPreparedStatementHandle] [Jetty-8 ] DEBUG - marking prepared statement handle as closed
      09-12-11 13:35:08,953 [AbstractBatcher ] [Jetty-8 ] WARN - exception clearing maxRows/queryTimeout
      java.sql.SQLException: 'Statement' already closed.
      at org.apache.derby.client.am.SQLExceptionFactory40.getSQLException(Unknown Source)
      at org.apache.derby.client.am.SqlException.getSQLException(Unknown Source)
      at org.apache.derby.client.am.Statement.getMaxRows(Unknown Source)
      at bitronix.tm.resource.jdbc.JdbcPreparedStatementHandle.getMaxRows(JdbcPreparedStatementHandle.java:208)
      at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:298)
      at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:234)
      at org.hibernate.loader.Loader.doQuery(Loader.java:749)
      at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
      at org.hibernate.loader.Loader.doList(Loader.java:2232)
      at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2129)
      at org.hibernate.loader.Loader.list(Loader.java:2124)
      at org.hibernate.loader.criteria.CriteriaLoader.list(CriteriaLoader.java:118)
      at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1597)
      at org.hibernate.impl.CriteriaImpl.list(CriteriaImpl.java:306)
      at org.ziptie.provider.tools.PluginProvider.getExecutionDetails(PluginProvider.java:77)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at org.ziptie.server.security.SecurityHandler.invoke(SecurityHandler.java:106)
      at $Proxy78.getExecutionDetails(Unknown Source)
      at org.ziptie.provider.tools.PluginProviderDelegate.getExecutionDetails(PluginProviderDelegate.java:25)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at com.sun.xml.ws.api.server.InstanceResolver$1.invoke(InstanceResolver.java:246)
      at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:146)
      at com.sun.xml.ws.server.sei.EndpointMethodHandler.invoke(EndpointMethodHandler.java:257)
      at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:93)
      at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:595)
      at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:554)
      at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:539)
      at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:436)
      at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:243)
      at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:444)
      at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:244)
      at com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAdapter.java:135)
      at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doGet(WSServletDelegate.java:129)
      at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doPost(WSServletDelegate.java:160)
      at org.ziptie.zap.metro.ZwsServlet.doPost(ZwsServlet.java:263)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
      at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
      at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
      at org.ziptie.server.security.ZSecurityFilter.doFilter(ZSecurityFilter.java:62)
      at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
      at org.ziptie.zap.metro.ZThreadContextFilter.doFilter(ZThreadContextFilter.java:34)
      at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
      at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
      at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
      at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
      at org.ziptie.zap.web.internal.ZContext.handle(ZContext.java:133)
      at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
      at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
      at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
      at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
      at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
      at org.mortbay.jetty.Server.handle(Server.java:326)
      at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
      at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:938)
      at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:755)
      at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
      at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
      at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
      at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)
      Caused by: org.apache.derby.client.am.SqlException: 'Statement' already closed.
      at org.apache.derby.client.am.Statement.checkForClosedStatement(Unknown Source)
      ... 64 more
      09-12-11 13:35:09,062 [bcPreparedStatementHandle] [Jetty-8 ] DEBUG - marking prepared statement handle as closed
      09-12-11 13:35:09,062 [JdbcConnectionHandle ] [Jetty-8 ] DEBUG - closing a JdbcConnectionHandle of a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f on org.apache.derby.client.am.LogicalConnection40@1908558
      09-12-11 13:35:09,062 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - releasing to pool a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - delisting a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f from a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=ACTIVE, 1 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - current transaction GTRID is [6E65746C642D31000001257C04D32E00000761]
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - resource GTRID is [6E65746C642D31000001257C04D32E00000761]
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - resource is in enlisting global transaction context: a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - requeuing a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f from a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=ACTIVE, 1 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - current transaction GTRID is [6E65746C642D31000001257C04D32E00000761]
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - resource GTRID is [6E65746C642D31000001257C04D32E00000761]
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - resource is in enlisting global transaction context: a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - deferring release to pool of a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f is not already registered for deferred release in a Bitronix Transaction with GTRID [6E65746C642D31000001257C04D32E00000761], status=ACTIVE, 1 resource(s) enlisted (started Fri Dec 11 04:35:08 GMT+00:00 2009)
      09-12-11 13:35:09,062 [TransactionContextHelper ] [Jetty-8 ] DEBUG - registering DeferredReleaseSynchronization for a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [AbstractXAStatefulHolder ] [Jetty-8 ] DEBUG - notifying 2 stateChangeEventListener(s) about state changing from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [AbstractXAStatefulHolder ] [Jetty-8 ] DEBUG - state changing from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource ziptie-ds in state ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [AbstractXAStatefulHolder ] [Jetty-8 ] DEBUG - notifying 2 stateChangeEventListener(s) about state changed from ACCESSIBLE to NOT_ACCESSIBLE in a JdbcPooledConnection from datasource ziptie-ds in state NOT_ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [JdbcPooledConnection ] [Jetty-8 ] DEBUG - released to pool a JdbcPooledConnection from datasource ziptie-ds in state NOT_ACCESSIBLE wrapping org.apache.derby.client.ClientXAConnection40@15bf05f
      09-12-11 13:35:09,062 [JDBCExceptionReporter ] [Jetty-8 ] WARN - SQL Error: 20000, SQLState: XCL16
      09-12-11 13:35:09,062 [JDBCExceptionReporter ] [Jetty-8 ] ERROR - ResultSet not open. Verify that autocommit is OFF.

      At 09-12-11 13:35:08,734 and 09-12-11 13:35:08,953 statements are evicted from the statement cache. From my reading of the code, eviction occurs during a 'put' into a 'full' LruMap. The eviction listener (an anonymous class in the JdbcPooledConnection constructor) performs a close of the evicted statement. The problem, it seems, is that the evicted PreparedStatement may be "outstanding" – i.e. it may have been issued from the pool during the current transaction – and thus later use of this statement within the context of the transaction will fail. It seems the "evictOne()" method in LruMap will always evict at least one statement, even if every statement in the cache is in-use.

      It also appears that the 'usage' counter is primarily (exclusively?) used to gauge how much the statement is used, and to therefore evict the least used statement. However, it seems that what needs to occur is a true reference counting of "check-out" and "check-in" from the cache, and a policy to never evict an in-use statement even if the max cache size would ultimately be exceeded.

      Because of the possibility of eviction of in-use statements, it is not possible to determine a reasonable maximum cache size. For example, currently my statement cache is 50 statements. Increasing the size to 100 might avoid the issue, provided that there are less than 100 unique prepared statements in my application. However, as soon as there are 101 possible prepared statements, the problem would recur.

        Activity

        Hide
        Brett Wooldridge added a comment - - edited

        Potential bug in my JdbcPreparedStatementHandle.hashCode() implementation.

        JdbcPreparedStatementHandle.java
            public int hashCode() {
                return sql != null ? sql.hashCode() : this.hashCode();
            }
        

        should be changed to:

        JdbcPreparedStatementHandle.java
            public int hashCode() {
                return sql != null ? sql.hashCode() : System.identityHashCode(this);
            } 
        

        It's an edge case, I don't think it's actually possible to prepare a statement where the SQL is null, but were it possible, the original hashCode() would infinite loop in the null SQL case.

        Show
        Brett Wooldridge added a comment - - edited Potential bug in my JdbcPreparedStatementHandle.hashCode() implementation. JdbcPreparedStatementHandle.java public int hashCode() { return sql != null ? sql.hashCode() : this .hashCode(); } should be changed to: JdbcPreparedStatementHandle.java public int hashCode() { return sql != null ? sql.hashCode() : System .identityHashCode( this ); } It's an edge case, I don't think it's actually possible to prepare a statement where the SQL is null, but were it possible, the original hashCode() would infinite loop in the null SQL case.
        Hide
        Ludovic Orban added a comment -

        Brett,

        Your explanation is very helpful, I'll keep an eye on it when I find the time to work on this issue.

        I have a few open questions, I hope you don't mind answering them:

        • What does the code do in case the prepared statement cache is disabled? I'm asking this because you also need to keep track of prepared statements event when they're not cached to close them all when the connection is closed.
        • What does the code do when the cache is full and all statements are in use?
        • What does the code do when the connection is closed but some prepared statements weren't closed?

        Thanks,
        Ludovic

        Show
        Ludovic Orban added a comment - Brett, Your explanation is very helpful, I'll keep an eye on it when I find the time to work on this issue. I have a few open questions, I hope you don't mind answering them: What does the code do in case the prepared statement cache is disabled? I'm asking this because you also need to keep track of prepared statements event when they're not cached to close them all when the connection is closed. What does the code do when the cache is full and all statements are in use? What does the code do when the connection is closed but some prepared statements weren't closed? Thanks, Ludovic
        Hide
        Brett Wooldridge added a comment -

        Ludovic, please get the latest patch. I went through and cleaned up to to minimize the diff between the old and new versions. Even though the behavioral change may sound large, when you see the diffs I think you'll see the changes are actually minimal.

        Q: What does the code do in case the prepared statement cache is disabled? I'm asking this because you also need to keep track of prepared statements event when they're not cached to close them all when the connection is closed.

        A: The existing code in that case is unchanged.

        Q: What does the code do when the cache is full and all statements are in use?

        A: When the cache is full and all statements are in use, if a new statement is prepared then the cache will exceed it's maximum size. However, it will return to maxSize as soon as possible. In the prior code the evictOne() method would evict one statement. In the new code, when a put occurs and the maxSize is exceeded, least-recently-used non-in-use statements are evicted until the cache reaches maxSize again. As noted, if everything in the cache is in use, nothing can be evicted and therefore the cache will temporarily exceed maxSize. In practice, with a cache of 50 statements or so it is hard to imagine this ever happening. When I reduced the maxSize to 5 my server would occasionally exceed the cache by two or three statements.

        Q: What does the code do when the connection is closed but some prepared statements weren't closed?

        A: The existing code in that case is unchanged.

        Three files are changed in the patch, and one was added.

        JdbcPooledConnection.java - virutally unchanged. It constructs a LruStatementCache rather than LruMap. log statement moved to cache.

        JdbcConnectionHandle.java - minimal changes to existing code. Uses JdbcPreparedStatementHandle as cache key, rather than SQL string.

        JdbcPreparedStatementHandle.java - previously had one constructor, added constructors to match all JDBC PreparedStatement constructors. added equals/hashCode methods so it compares full state and can be used as a hash key. close() now calls back to the cache to update usage counter.

        LruStatementCache - new class, modeled on LruMap. where all the real work is done. simple, fully documented, and I believe very clear in it's function.

        Show
        Brett Wooldridge added a comment - Ludovic, please get the latest patch. I went through and cleaned up to to minimize the diff between the old and new versions. Even though the behavioral change may sound large, when you see the diffs I think you'll see the changes are actually minimal. Q: What does the code do in case the prepared statement cache is disabled? I'm asking this because you also need to keep track of prepared statements event when they're not cached to close them all when the connection is closed. A: The existing code in that case is unchanged. Q: What does the code do when the cache is full and all statements are in use? A: When the cache is full and all statements are in use, if a new statement is prepared then the cache will exceed it's maximum size. However, it will return to maxSize as soon as possible. In the prior code the evictOne() method would evict one statement. In the new code, when a put occurs and the maxSize is exceeded, least-recently-used non-in-use statements are evicted until the cache reaches maxSize again. As noted, if everything in the cache is in use, nothing can be evicted and therefore the cache will temporarily exceed maxSize. In practice, with a cache of 50 statements or so it is hard to imagine this ever happening. When I reduced the maxSize to 5 my server would occasionally exceed the cache by two or three statements. Q: What does the code do when the connection is closed but some prepared statements weren't closed? A: The existing code in that case is unchanged. Three files are changed in the patch, and one was added. JdbcPooledConnection.java - virutally unchanged. It constructs a LruStatementCache rather than LruMap. log statement moved to cache. JdbcConnectionHandle.java - minimal changes to existing code. Uses JdbcPreparedStatementHandle as cache key, rather than SQL string. JdbcPreparedStatementHandle.java - previously had one constructor, added constructors to match all JDBC PreparedStatement constructors. added equals/hashCode methods so it compares full state and can be used as a hash key. close() now calls back to the cache to update usage counter. LruStatementCache - new class, modeled on LruMap. where all the real work is done. simple, fully documented, and I believe very clear in it's function.
        Hide
        Brett Wooldridge added a comment -

        PreparedStatement usage is now tracked, and in-use statements will not be retired from the cache until they are no longer in-use.

        Show
        Brett Wooldridge added a comment - PreparedStatement usage is now tracked, and in-use statements will not be retired from the cache until they are no longer in-use.
        Hide
        Ludovic Orban added a comment -

        Excellent work Brett!

        Show
        Ludovic Orban added a comment - Excellent work Brett!

          People

          • Assignee:
            Brett Wooldridge
            Reporter:
            Brett Wooldridge
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: