[jboss-jira] [JBoss JIRA] Commented: (JBJCA-676) Evicted and closed CachedPreparedStatement leased out again on next call to prepareStatement by LIRS cache.

[Jeremy Whiting (JIRA)]

    [ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12630531#comment-12630531 ] 

Jeremy Whiting commented on JBJCA-676:
--------------------------------------

 Some research into the LIRS eviction policy has revealed the cause of the closed statement exceptions. LIRS splits the cache into two sections called 'high' and 'low'. An item is located in each section depending on it's recency (how often and how recently) it is accessed.
 The org.jboss.jca.adapters.jdbc.util.BoundedConcurrentHashMap object provides an EvictionListener and each eviction policy implements the onEntryEviction(evicted) method. The implementation of this listener closes the underlying PreparedStatement. See org.jboss.jca.adapters.jdbc.PreparedStatementCache.PreparedStatementEvictionListener.
 What distinguishes the LIRS to the LRU policy is when the onEntryEviction is called. With LRU the eviction listener will be called when the least used item is evicted. But with LIRS the listener is also called when an item is demoted from 'low' to the 'high' section.  The item remains in the cache and is not flushed. This means the PreparedStatementCache will have an item which is marked as closed. This is a problem in the current PreparedStatementCache because an item is not checking it's closed status before passing the object to the caller of prepareStatement(...).

 To prove these finding a junit test case is provided demonstrating the behaviour of the cache. It is a Maven project and the test case is called using the normal plugin call,  $ mvn test

 The test will fail on the last assert statement showing the mock PreparedStatement was closed by the cache. Even though it remains in the cache.

> Evicted and closed CachedPreparedStatement leased out again on next call to prepareStatement by LIRS cache.
> -----------------------------------------------------------------------------------------------------------
>
>                 Key: JBJCA-676
>                 URL: https://issues.jboss.org/browse/JBJCA-676
>             Project: IronJacamar
>          Issue Type: Bug
>          Components: JDBC
>    Affects Versions: 1.0.4.Final
>         Environment: Using MySQL5 database on linux.
>            Reporter: Jeremy Whiting
>            Assignee: Jesper Pedersen
>         Attachments: added-logging-messages.diff, as7.1-server-log-extract.txt
>
>
>  My application throws an exception that reports the PreparedStatement cannot be used after it is closed. The exception is 
> javax.persistence.PersistenceException: org.hibernate.exception.JDBCConnectionException: No operations allowed after statement closed.
>  It appears the PreparedStatementCache is not flushing an evicted item from the cache. The cache does call PreparedStatementEvictionListener.onEntryEviction(Map) which closes all the cached items being evicted. But it does not remove the item from the cache in that same call.
>  When a client then calls prepareStatement(String) using the identical sql as a cached item the lookup in the cache returns the closed CachedPreparedStatement.
>  I have a test case that calls the transaction on the server. The client makes an EJB call using a web service endpoint. The test case only executes one client call at a time.
> Observed behaviour
>  This behaviour has only been seen to occur when eviction and prepare call are for identical SQL and when no other JDBC work happens between the two calls. Additionally it is timing sensitive. Turning on DEBUG logging makes the issue go away. To generate the logs attached I used a ramdisk and an ASYNC logging appender to eliminate delays due to saving to disk.
>  Attached are logs with DEBUG level messages turned on for these categories: org.hibernate.SQL, org.hibernate.engine.jdbc.internal.JdbcResourceRegistryImpl and jboss.jdbc.spy
>  To highlight the behaviour I added two logging messages. Source files are attached as a diff.
> a) The first is when items in the cache are evicted. The log message shows the hash identity of the CachedPreparedStatement and the SQL statement. Message added to org.jboss.jca.adapters.jdbc.PreparedStatementCache.onEntryEviction(Map) on line 255.
> b) The second is just before the first parameter (a String) is bound to a PreparedStatement. The message logs the hash identity of the CachedPreparedStatement, the SQL and hashed identity of the underlying driver com.mysql.jdbc.JDBC4PreparedStatement. The message is added to org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.setString(int, String) on line 637
>  The log file shows the two events that match the behaviour detailed earlier. The log file is an small extract of the original. The first (the eviction) on line 21 and the second (the parameter binding) on 24.
>  A test case will follow with an attempt to use H2 rather than MySQL.

--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira