diff --git a/hibernate-core/src/main/java/org/hibernate/cache/spi/UpdateTimestampsCache.java b/hibernate-core/src/main/java/org/hibernate/cache/spi/UpdateTimestampsCache.java index f369d421d5..5169024d85 100644 --- a/hibernate-core/src/main/java/org/hibernate/cache/spi/UpdateTimestampsCache.java +++ b/hibernate-core/src/main/java/org/hibernate/cache/spi/UpdateTimestampsCache.java @@ -33,6 +33,7 @@ import org.jboss.logging.Logger; import org.hibernate.HibernateException; import org.hibernate.cache.CacheException; import org.hibernate.cfg.Settings; +import org.hibernate.engine.spi.SessionFactoryImplementor; import org.hibernate.internal.CoreMessageLogger; /** @@ -53,8 +54,10 @@ public class UpdateTimestampsCache { private ReentrantReadWriteLock readWriteLock = new ReentrantReadWriteLock(); private final TimestampsRegion region; + private final SessionFactoryImplementor factory; - public UpdateTimestampsCache(Settings settings, Properties props) throws HibernateException { + public UpdateTimestampsCache(Settings settings, Properties props, final SessionFactoryImplementor factory) throws HibernateException { + this.factory = factory; String prefix = settings.getCacheRegionPrefix(); String regionName = prefix == null ? REGION_NAME : prefix + '.' + REGION_NAME; LOG.startingUpdateTimestampsCache(regionName); @@ -74,6 +77,9 @@ public class UpdateTimestampsCache { //put() has nowait semantics, is this really appropriate? //note that it needs to be async replication, never local or sync region.put( space, ts ); + if ( factory.getStatistics().isStatisticsEnabled() ) { + factory.getStatisticsImplementor().updateTimestampsCachePut(); + } } //TODO: return new Lock(ts); } @@ -96,6 +102,9 @@ public class UpdateTimestampsCache { //put() has nowait semantics, is this really appropriate? //note that it needs to be async replication, never local or sync region.put( space, ts ); + if ( factory.getStatistics().isStatisticsEnabled() ) { + factory.getStatisticsImplementor().updateTimestampsCachePut(); + } } } finally { @@ -111,6 +120,9 @@ public class UpdateTimestampsCache { for ( Serializable space : (Set) spaces ) { Long lastUpdate = (Long) region.get( space ); if ( lastUpdate == null ) { + if ( factory.getStatistics().isStatisticsEnabled() ) { + factory.getStatisticsImplementor().updateTimestampsCacheMiss(); + } //the last update timestamp was lost from the cache //(or there were no updates since startup!) //updateTimestamps.put( space, new Long( updateTimestamps.nextTimestamp() ) ); @@ -118,6 +130,9 @@ public class UpdateTimestampsCache { } else { LOG.debugf("[%s] last update timestamp: %s", space, lastUpdate + ", result set timestamp: " + timestamp); + if ( factory.getStatistics().isStatisticsEnabled() ) { + factory.getStatisticsImplementor().updateTimestampsCacheHit(); + } if ( lastUpdate.longValue() >= timestamp.longValue() ) return false; } } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java index f5a04c4f77..6ff2ff8fe0 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java @@ -1534,4 +1534,17 @@ public interface CoreMessageLogger extends BasicLogger { @LogMessage(level = WARN) @Message(value = "There were not column names specified for index %s on table %s", id = 432) void noColumnsSpecifiedForIndex(String indexName, String tableName); + + @LogMessage(level = INFO) + @Message(value = "update timestamps cache puts: %s", id = 433) + void timestampCachePuts(long updateTimestampsCachePutCount); + + @LogMessage(level = INFO) + @Message(value = "update timestamps cache hits: %s", id = 434) + void timestampCacheHits(long updateTimestampsCachePutCount); + + @LogMessage(level = INFO) + @Message(value = "update timestamps cache misses: %s", id = 435) + void timestampCacheMisses(long updateTimestampsCachePutCount); + } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java index 334ce84151..9288e3fe77 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java @@ -452,7 +452,7 @@ public final class SessionFactoryImpl currentSessionContext = buildCurrentSessionContext(); if ( settings.isQueryCacheEnabled() ) { - updateTimestampsCache = new UpdateTimestampsCache(settings, properties); + updateTimestampsCache = new UpdateTimestampsCache(settings, properties, this); queryCache = settings.getQueryCacheFactory() .getQueryCache(null, updateTimestampsCache, settings, properties); queryCaches = new HashMap(); @@ -775,7 +775,7 @@ public final class SessionFactoryImpl currentSessionContext = buildCurrentSessionContext(); if ( settings.isQueryCacheEnabled() ) { - updateTimestampsCache = new UpdateTimestampsCache( settings, properties ); + updateTimestampsCache = new UpdateTimestampsCache( settings, properties, this ); queryCache = settings.getQueryCacheFactory() .getQueryCache( null, updateTimestampsCache, settings, properties ); queryCaches = new HashMap(); diff --git a/hibernate-core/src/main/java/org/hibernate/jmx/StatisticsService.java b/hibernate-core/src/main/java/org/hibernate/jmx/StatisticsService.java index f134b72aef..f176e1376d 100644 --- a/hibernate-core/src/main/java/org/hibernate/jmx/StatisticsService.java +++ b/hibernate-core/src/main/java/org/hibernate/jmx/StatisticsService.java @@ -184,6 +184,19 @@ public class StatisticsService implements StatisticsServiceMBean { public long getQueryCachePutCount() { return stats.getQueryCachePutCount(); } + + public long getUpdateTimestampsCacheHitCount() { + return stats.getUpdateTimestampsCacheHitCount(); + } + + public long getUpdateTimestampsCacheMissCount() { + return stats.getUpdateTimestampsCacheMissCount(); + } + + public long getUpdateTimestampsCachePutCount() { + return stats.getUpdateTimestampsCachePutCount(); + } + /** * @see StatisticsServiceMBean#getFlushCount() */ diff --git a/hibernate-core/src/main/java/org/hibernate/stat/Statistics.java b/hibernate-core/src/main/java/org/hibernate/stat/Statistics.java index f8ac25b076..e8b935b0a9 100755 --- a/hibernate-core/src/main/java/org/hibernate/stat/Statistics.java +++ b/hibernate-core/src/main/java/org/hibernate/stat/Statistics.java @@ -123,6 +123,18 @@ public interface Statistics { * Get the global number of cacheable queries put in cache */ public long getQueryCachePutCount(); + /** + * Get the global number of timestamps successfully retrieved from cache + */ + public long getUpdateTimestampsCacheHitCount(); + /** + * Get the global number of tables for which no update timestamps was *not* found in cache + */ + public long getUpdateTimestampsCacheMissCount(); + /** + * Get the global number of timestamps put in cache + */ + public long getUpdateTimestampsCachePutCount(); /** * Get the global number of flush executed by sessions (either implicit or explicit) */ diff --git a/hibernate-core/src/main/java/org/hibernate/stat/internal/ConcurrentStatisticsImpl.java b/hibernate-core/src/main/java/org/hibernate/stat/internal/ConcurrentStatisticsImpl.java index 3b7ec65008..295f409a62 100644 --- a/hibernate-core/src/main/java/org/hibernate/stat/internal/ConcurrentStatisticsImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/stat/internal/ConcurrentStatisticsImpl.java @@ -84,6 +84,10 @@ public class ConcurrentStatisticsImpl implements StatisticsImplementor, Service private AtomicLong queryCacheMissCount = new AtomicLong(); private AtomicLong queryCachePutCount = new AtomicLong(); + private AtomicLong updateTimestampsCacheHitCount = new AtomicLong(); + private AtomicLong updateTimestampsCacheMissCount = new AtomicLong(); + private AtomicLong updateTimestampsCachePutCount = new AtomicLong(); + private AtomicLong committedTransactionCount = new AtomicLong(); private AtomicLong transactionCount = new AtomicLong(); @@ -151,6 +155,10 @@ public class ConcurrentStatisticsImpl implements StatisticsImplementor, Service queryCacheMissCount.set( 0 ); queryCachePutCount.set( 0 ); + updateTimestampsCacheMissCount.set( 0 ); + updateTimestampsCacheHitCount.set( 0 ); + updateTimestampsCachePutCount.set( 0 ); + transactionCount.set( 0 ); committedTransactionCount.set( 0 ); @@ -374,6 +382,21 @@ public class ConcurrentStatisticsImpl implements StatisticsImplementor, Service slcs.incrementPutCount(); } + @Override + public void updateTimestampsCacheHit() { + updateTimestampsCacheHitCount.getAndIncrement(); + } + + @Override + public void updateTimestampsCacheMiss() { + updateTimestampsCacheMissCount.getAndIncrement(); + } + + @Override + public void updateTimestampsCachePut() { + updateTimestampsCachePutCount.getAndIncrement(); + } + /** * Query statistics from query string (HQL or SQL) * @@ -446,6 +469,18 @@ public class ConcurrentStatisticsImpl implements StatisticsImplementor, Service return queryCachePutCount.get(); } + public long getUpdateTimestampsCacheHitCount() { + return updateTimestampsCacheHitCount.get(); + } + + public long getUpdateTimestampsCacheMissCount() { + return updateTimestampsCacheMissCount.get(); + } + + public long getUpdateTimestampsCachePutCount() { + return updateTimestampsCachePutCount.get(); + } + /** * @return flush */ @@ -568,6 +603,9 @@ public class ConcurrentStatisticsImpl implements StatisticsImplementor, Service LOG.collectionsFetched(collectionFetchCount.get()); LOG.queriesExecuted(queryExecutionCount.get()); LOG.queryCachePuts(queryCachePutCount.get()); + LOG.timestampCachePuts( updateTimestampsCachePutCount.get() ); + LOG.timestampCacheHits( updateTimestampsCacheHitCount.get() ); + LOG.timestampCacheMisses( updateTimestampsCacheMissCount.get() ); LOG.queryCacheHits(queryCacheHitCount.get()); LOG.queryCacheMisses(queryCacheMissCount.get()); LOG.maxQueryTime(queryExecutionMaxTime.get()); @@ -709,6 +747,9 @@ public class ConcurrentStatisticsImpl implements StatisticsImplementor, Service .append( ",query cache puts=" ).append( queryCachePutCount ) .append( ",query cache hits=" ).append( queryCacheHitCount ) .append( ",query cache misses=" ).append( queryCacheMissCount ) + .append(",update timestamps cache puts=").append(updateTimestampsCachePutCount) + .append(",update timestamps cache hits=").append(updateTimestampsCacheHitCount) + .append(",update timestamps cache misses=").append(updateTimestampsCacheMissCount) .append( ",max query time=" ).append( queryExecutionMaxTime ) .append( ']' ) .toString(); diff --git a/hibernate-core/src/main/java/org/hibernate/stat/spi/StatisticsImplementor.java b/hibernate-core/src/main/java/org/hibernate/stat/spi/StatisticsImplementor.java index f43bd0efc4..a9c1c6cb07 100644 --- a/hibernate-core/src/main/java/org/hibernate/stat/spi/StatisticsImplementor.java +++ b/hibernate-core/src/main/java/org/hibernate/stat/spi/StatisticsImplementor.java @@ -204,4 +204,20 @@ public interface StatisticsImplementor extends Statistics, Service { * @param time execution time */ public void queryExecuted(String hql, int rows, long time); + + + /** + * Callback indicating a hit to the timestamp cache + */ + public void updateTimestampsCacheHit(); + + /** + * Callback indicating a miss to the timestamp cache + */ + public void updateTimestampsCacheMiss(); + + /** + * Callback indicating a put to the timestamp cache + */ + public void updateTimestampsCachePut(); } \ No newline at end of file diff --git a/hibernate-core/src/matrix/java/org/hibernate/test/tm/CMTTest.java b/hibernate-core/src/matrix/java/org/hibernate/test/tm/CMTTest.java index aeef47c9fc..09d50971e3 100755 --- a/hibernate-core/src/matrix/java/org/hibernate/test/tm/CMTTest.java +++ b/hibernate-core/src/matrix/java/org/hibernate/test/tm/CMTTest.java @@ -80,6 +80,9 @@ public class CMTTest extends BaseCoreFunctionalTestCase { @Test public void testConcurrent() throws Exception { sessionFactory().getStatistics().clear(); + assertEquals( 0, sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount() ); + assertEquals( 0, sessionFactory().getStatistics().getUpdateTimestampsCachePutCount() ); + assertEquals( 0, sessionFactory().getStatistics().getUpdateTimestampsCacheMissCount() ); assertNotNull( sessionFactory().getEntityPersister( "Item" ).getCacheAccessStrategy() ); assertEquals( 0, sessionFactory().getStatistics().getEntityLoadCount() ); @@ -94,6 +97,9 @@ public class CMTTest extends BaseCoreFunctionalTestCase { bar.put( "description", "a small bar" ); s.persist( "Item", bar ); TestingJtaBootstrap.INSTANCE.getTransactionManager().commit(); + assertEquals(0, sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount()); + assertEquals(3, sessionFactory().getStatistics().getUpdateTimestampsCachePutCount()); // Twice preinvalidate & one invalidate + assertEquals(0, sessionFactory().getStatistics().getUpdateTimestampsCacheMissCount()); sessionFactory().evictEntity( "Item" ); @@ -139,6 +145,8 @@ public class CMTTest extends BaseCoreFunctionalTestCase { assertEquals( 3, sessionFactory().getStatistics().getQueryExecutionCount() ); assertEquals( 0, sessionFactory().getStatistics().getQueryCacheHitCount() ); assertEquals( 0, sessionFactory().getStatistics().getQueryCacheMissCount() ); + assertEquals( 0, sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount() ); + assertEquals( 3, sessionFactory().getStatistics().getUpdateTimestampsCachePutCount() ); TestingJtaBootstrap.INSTANCE.getTransactionManager().begin(); s = openSession(); @@ -194,6 +202,8 @@ public class CMTTest extends BaseCoreFunctionalTestCase { assertEquals( sessionFactory().getStatistics().getQueryCachePutCount(), 1 ); assertEquals( sessionFactory().getStatistics().getQueryCacheHitCount(), 1 ); assertEquals( sessionFactory().getStatistics().getQueryCacheMissCount(), 1 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount(), 1 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCachePutCount(), 0 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().resume( tx1 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().commit(); @@ -212,6 +222,9 @@ public class CMTTest extends BaseCoreFunctionalTestCase { assertEquals( sessionFactory().getStatistics().getQueryCachePutCount(), 1 ); assertEquals( sessionFactory().getStatistics().getQueryCacheHitCount(), 2 ); assertEquals( sessionFactory().getStatistics().getQueryCacheMissCount(), 1 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount(), 2 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCachePutCount(), 0 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheMissCount(), 0 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().resume( tx4 ); List r4 = s4.createCriteria( "Item" ).addOrder( Order.asc( "description" ) ) @@ -227,6 +240,9 @@ public class CMTTest extends BaseCoreFunctionalTestCase { assertEquals( sessionFactory().getStatistics().getQueryCachePutCount(), 1 ); assertEquals( sessionFactory().getStatistics().getQueryCacheHitCount(), 3 ); assertEquals( sessionFactory().getStatistics().getQueryCacheMissCount(), 1 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount(), 3 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCachePutCount(), 0 ); + TestingJtaBootstrap.INSTANCE.getTransactionManager().begin(); s = openSession(); @@ -289,9 +305,13 @@ public class CMTTest extends BaseCoreFunctionalTestCase { assertEquals( sessionFactory().getStatistics().getQueryCachePutCount(), 2 ); assertEquals( sessionFactory().getStatistics().getQueryCacheHitCount(), 0 ); assertEquals( sessionFactory().getStatistics().getQueryCacheMissCount(), 2 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount(), 4 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCachePutCount(), 2 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().resume( tx1 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().commit(); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCachePutCount(), 3 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount(), 5 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().begin(); Session s3 = openSession(); @@ -307,6 +327,7 @@ public class CMTTest extends BaseCoreFunctionalTestCase { assertEquals( sessionFactory().getStatistics().getQueryCachePutCount(), 3 ); assertEquals( sessionFactory().getStatistics().getQueryCacheHitCount(), 0 ); assertEquals( sessionFactory().getStatistics().getQueryCacheMissCount(), 3 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount(), 6 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().resume( tx4 ); List r4 = s4.createCriteria( "Item" ).addOrder( Order.asc( "description" ) ) @@ -322,6 +343,7 @@ public class CMTTest extends BaseCoreFunctionalTestCase { assertEquals( sessionFactory().getStatistics().getQueryCachePutCount(), 3 ); assertEquals( sessionFactory().getStatistics().getQueryCacheHitCount(), 1 ); assertEquals( sessionFactory().getStatistics().getQueryCacheMissCount(), 3 ); + assertEquals( sessionFactory().getStatistics().getUpdateTimestampsCacheHitCount(), 7 ); TestingJtaBootstrap.INSTANCE.getTransactionManager().begin(); s = openSession();