[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jeremy Whiting updated JBJCA-676: --------------------------------- Attachment: as7.1-server-log-extract.txt Extract of AS7.1 server log. -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jeremy Whiting updated JBJCA-676: --------------------------------- Description: 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. was: My application throws an exception that reports the PreparedStatement cannot be used after it is 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

[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jeremy Whiting updated JBJCA-676: --------------------------------- Attachment: evictionTest.tar Test case demonstrating eviction listener being called even though the cache item remains. -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jeremy Whiting commented on JBJCA-676: -------------------------------------- It comes down to semantics. LIRS is evicting the item from one section so really it is valid for this eviction policy implementation to call the listener. -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jeremy Whiting commented on JBJCA-676: -------------------------------------- I have replaced the version of BoundedConcurrentHashMap. The behaviour of the cache is not consistent and more test cases are showing these irregularities. The test case has been updated and is in the file named 'evictionTest-with-patched-BoundedConcurrentHashMap.tar'. -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jeremy Whiting updated JBJCA-676: --------------------------------- Workaround Description: I have found a workaround for this exception. By switching the cache eviction policy from LIRS to LRU this issue is no longer a problem. You will need to switch the ENUM in the constructor of PreparedStatementCache located here ironjacamar/adapters/src/main/java/org/jboss/jca/adapters/jdbc/PreparedStatementCache.java and replace the generated artifact here in a typical AS7.1 installation modules/org/jboss/ironjacamar/jdbcadapters/main/ironjacamar-jdbc-1.0.4.Final.jar Workaround: [Workaround Exists] -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jeremy Whiting commented on JBJCA-676: -------------------------------------- Some suggestions for initialising the BCHM have improved the test case failures. By setting the concurrency lower than the cache size items are no-longer evicted in error. An updated test case shows for items are not evicted. Which is the expected behaviour. There are 3 test cases. 1) this fails. It uses the first instance of BCHM. cache size 8 and does not correctly manage the number of items in the cache. 2) passes, second instance of BCHM, cache size 8. identical test to 1. 3) passes, cache size of 3. It checks the BCHM behaviour matches the example in academic paper. Also, contrary to my earlier thoughts an item demoted from Lo to Hi *should not* have the eviction listener called. This no longer occurs using the patched version of BCHM. -- This message is automatically generated by JIRA. For more information on JIRA, see: http://www.atlassian.com/software/jira

[ https://issues.jboss.org/browse/JBJCA-676?page=com.atlassian.jira.plugin.... ] Jesper Pedersen resolved JBJCA-676. ----------------------------------- Fix Version/s: 1.1.0.Alpha3 Resolution: Done The default cache policy has changed to LRU_OLD. The cache policy can be changed by setting the system property "ironjacamar.jdbc.cache" to LRU, LRU_OLD or LIRS. -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.jboss.org/secure/ContactAdministrators!default.jspa For more information on JIRA, see: http://www.atlassian.com/software/jira