Added stats for UpdateTimestamp region

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<Serializable>) 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;
 				}
 			}

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);
+
 }

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<String,QueryCache>();
@@ -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<String,QueryCache>();

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()
 	 */

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)
      */

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();

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();
 }

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();