Hi,
we are experiencing performance problems on production servers, which is associated with query cache. Apparently there is a SessionFactory-wide lock on the single instance of UpdateTimestampCache class. This lock is causing significant blocking issues on servers with 8 and more cores.
These are the methods in question:
Code:
public class UpdateTimestampsCache {
...
public synchronized void preinvalidate(Serializable[] spaces) throws CacheException {
...
public synchronized void invalidate(Serializable[] spaces) throws CacheException {
...
public synchronized boolean isUpToDate(Set spaces, Long timestamp) throws HibernateException {
...
Thread telemetry screenshot from YourKit:
Monitor backtrace report generated by YourKit:
Code:
Back traces
+-----------------------------------------------------------------------------------------------------------------------------------------+---------------------+------------------+
| Name | Time (ms) | Count |
+-----------------------------------------------------------------------------------------------------------------------------------------+---------------------+------------------+
| +---org.hibernate.cache.UpdateTimestampsCache.invalidate(Serializable[]) | 37 639 178 62 % | 330 654 62 % |
| | | | | |
| | +---org.hibernate.engine.ActionQueue$AfterTransactionCompletionProcessQueue.afterTransactionCompletion(boolean) | | |
| | | | | |
| | +---org.hibernate.engine.ActionQueue.afterTransactionCompletion(boolean) | | |
| | | | | |
| | +---org.hibernate.impl.SessionImpl.afterTransactionCompletion(boolean, Transaction) | | |
| | | | | |
| | +---org.hibernate.jdbc.JDBCContext.afterNontransactionalQuery(boolean) | 33 492 067 55 % | 295 298 56 % |
| | | | | | |
| | | +---org.hibernate.impl.SessionImpl.afterOperation(boolean) | | |
| | | | | | |
| | | +---org.hibernate.impl.SessionImpl.list(String, QueryParameters) | 23 260 227 38 % | 205 708 39 % |
| | | | | | |
| | | +---org.hibernate.impl.SessionImpl.get(String, Serializable) | 8 948 485 15 % | 78 124 15 % |
| | | | | | |
| | | +---org.hibernate.impl.SessionImpl.list(CriteriaImpl) | 1 097 517 2 % | 9 674 2 % |
| | | | | | |
| | | +---org.hibernate.impl.SessionImpl.listCustomQuery(CustomQuery, QueryParameters) | 185 836 0 % | 1 792 0 % |
| | | | | |
| | +---org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(boolean, Transaction) | 3 607 634 6 % | 31 301 6 % |
| | | | | | |
| | | +---org.hibernate.transaction.JDBCTransaction.commit() | 1 858 608 3 % | 16 309 3 % |
| | | | | | |
| | | +---org.hibernate.jdbc.JDBCContext.connectionCleanedUp() | 1 743 032 3 % | 14 955 3 % |
| | | | | | |
| | | +---org.hibernate.transaction.JDBCTransaction.rollback() | 5 994 0 % | 37 0 % |
| | | | | |
| | +---org.springframework.orm.hibernate3.SpringSessionSynchronization.afterCompletion(int) | 539 476 1 % | 4 055 1 % |
| | | | |
| +---org.hibernate.cache.UpdateTimestampsCache.isUpToDate(Set, Long) | 22 618 644 37 % | 196 432 37 % |
| | | | | |
| | +---org.hibernate.cache.StandardQueryCache.isUpToDate(Set, Long) | | |
| | | | | |
| | +---org.hibernate.cache.StandardQueryCache.get(QueryKey, Type[], boolean, Set, SessionImplementor) | | |
| | | | | |
| | +---org.hibernate.loader.Loader.getResultFromQueryCache(SessionImplementor, QueryParameters, Set, Type[], QueryCache, QueryKey) | | |
| | | | | |
| | +---org.hibernate.loader.Loader.listUsingQueryCache(SessionImplementor, QueryParameters, Set, Type[]) | | |
| | | | | |
| | +---org.hibernate.loader.Loader.list(SessionImplementor, QueryParameters, Set, Type[]) | | |
| | | | | |
| | +---org.hibernate.loader.hql.QueryLoader.list(SessionImplementor, QueryParameters) | 22 353 852 37 % | 194 070 37 % |
| | | | | |
| | +---org.hibernate.loader.criteria.CriteriaLoader.list(SessionImplementor) | 163 625 0 % | 1 468 0 % |
| | | | | |
| | +---org.hibernate.loader.custom.CustomLoader.list(SessionImplementor, QueryParameters) | 101 165 0 % | 894 0 % |
| | | | |
| +---org.hibernate.cache.UpdateTimestampsCache.preinvalidate(Serializable[]) | 287 421 0 % | 2 328 0 % |
+-----------------------------------------------------------------------------------------------------------------------------------------+---------------------+------------------+
Generated by YourKit Java Profiler 8.0.19 8.9.2010 12:43:41
Judging from comments in UpdateTimestampsCache.java, this is a known (or at least anticipated) issue. Is there any workaround? Any plans on when this could be fixed?
We are using:
- Hibernate 3.5.0
- EhCache 2.1.0
- Apache Tomcat 5.5.23
- Java(TM) SE Runtime Environment (build 1.6.0_16-b01)
Java HotSpot(TM) 64-Bit Server VM (build 14.2-b01, mixed mode) - 64-bit GNU/Linux 2.6.18-164.el5xen
Thanks,
Mirek