HHH-12855 - Add query plan compilation statistics

documentation/src/main/asciidoc/userguide/chapters/statistics/Statistics.adoc

@@ -100,6 +100,8 @@ https://docs.jboss.org/hibernate/orm/{majorMinorVersion}/javadocs/org/hibernate/
 `getQueryExecutionCount`:: Get the global number of executed queries.
 `getQueryExecutionMaxTime`:: Get the time in milliseconds of the slowest query.
 `getQueryExecutionMaxTimeQueryString`:: Get the query string for the slowest query.
+`getQueryPlanCacheHitCount`:: Get the global number of query plans successfully retrieved from cache.
+`getQueryPlanCacheMissCount`:: Get the global number of query plans lookups *not* found in cache.
 
 [[statistics-natural-id]]
 ==== Natural id statistics methods
@@ -128,7 +130,7 @@ https://docs.jboss.org/hibernate/orm/{majorMinorVersion}/javadocs/org/hibernate/
 ===== Second-level cache query statistics methods
 
 `getQueryCacheHitCount`:: Get the global number of cached queries successfully retrieved from cache.
-`getQueryCacheMissCount`:: Get the global number of cached queries __not__ found in cache.
+`getQueryCacheMissCount`:: Get the global number of cached queries *not* found in cache.
 `getQueryCachePutCount`:: Get the global number of cacheable queries put in cache.
 
 [[statistics-second-level-cache-timestamp]]
@@ -153,7 +155,31 @@ raise the maximum number of queries that are being stored by the `Statistics` in
 If the maximum number of queries has been reached, Hibernate uses a https://en.wikipedia.org/wiki/Cache_replacement_policies#Least_recently_used_(LRU)[Least recently used (LRU)] policy
 to make room for new query entries.
 
+[[statistics-query-plan-cache]]
+=== Query plan cache statistics
 
+Every entity query, be it JPQL/HQL or Criteria API is compiled to an AST (Abstract Syntax Tree),
+and this process is resource-intensive.
+To speed up the entity query executions, Hibernate offers a query plan cache so that compiled plans can be reused.
 
+To monitor the query plan cache you have the following statistics.
 
+[[statistics-query-plan-cache-global-level]]
+==== Query plan cache global statistics
 
+The `Statistics` instance provides two global counters which can give you an overall picture of the query plan cache effectiveness.
+
+- `getQueryPlanCacheHitCount`
+- `getQueryPlanCacheMissCount`
+
+If the hit count is high and the miss count is low, then the query plan cache is effective, and the vast majority of entity queries
+are served from the query plan cache, rather than being compiled over and over again.
+
+[[statistics-query-plan-cache-query-level]]
+==== Query plan cache query-level statistics
+
+The `QueryStatistics` instance, which you can get via the `getQueryStatistics(String queryString)` method of the `Statistics` object, stores the following query plan cache metrics:
+
+`getPlanCacheHitCount`:: The number of query plans successfully fetched from the cache.
+`getQueryPlanCacheMissCount`:: The number of query plans *not* fetched from the cache.
+`getQueryPlanCacheMissCount`:: The overall time spent to compile the plan for this particular query.

hibernate-core/src/main/java/org/hibernate/engine/query/spi/QueryPlanCache.java

@@ -13,6 +13,7 @@ import java.util.HashMap;
 import java.util.HashSet;
 import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.TimeUnit;
 
 import org.hibernate.Filter;
 import org.hibernate.MappingException;
@@ -144,17 +145,32 @@ public class QueryPlanCache implements Serializable {
 	 * @throws MappingException Indicates a problem translating the query
 	 */
 	@SuppressWarnings("unchecked")
-	public HQLQueryPlan getHQLQueryPlan(String queryString, boolean shallow, Map<String,Filter> enabledFilters)
+	public HQLQueryPlan getHQLQueryPlan(String queryString, boolean shallow, Map<String, Filter> enabledFilters)
 			throws QueryException, MappingException {
 		final HQLQueryPlanKey key = new HQLQueryPlanKey( queryString, shallow, enabledFilters );
 		HQLQueryPlan value = (HQLQueryPlan) queryPlanCache.get( key );
+		boolean stats = factory.getStatistics().isStatisticsEnabled();
+
 		if ( value == null ) {
+			final long startTime = ( stats ) ? System.nanoTime() : 0L;
+
 			LOG.tracev( "Unable to locate HQL query plan in cache; generating ({0})", queryString );
 			value = new HQLQueryPlan( queryString, shallow, enabledFilters, factory );
+
+			if ( stats ) {
+				final long endTime = System.nanoTime();
+				final long microseconds = TimeUnit.MICROSECONDS.convert( endTime - startTime, TimeUnit.NANOSECONDS );
+				factory.getStatistics().queryCompiled( queryString, microseconds );
+			}
+
 			queryPlanCache.putIfAbsent( key, value );
 		}
 		else {
 			LOG.tracev( "Located HQL query plan in cache ({0})", queryString );
+
+			if ( stats ) {
+				factory.getStatistics().queryPlanCacheHit( queryString );
+			}
 		}
 		return value;
 	}

hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java

@@ -1824,4 +1824,11 @@ public interface CoreMessageLogger extends BasicLogger {
 			"The NotFoundAction.IGNORE @ManyToOne and @OneToOne associations are always fetched eagerly.", id = 491)
 	void ignoreNotFoundWithFetchTypeLazy(String entity, String association);
 
+	@LogMessage(level = INFO)
+	@Message(value = "Query plan cache hits: %s", id = 492)
+	void queryPlanCacheHits(long queryPlanCacheHitCount);
+
+	@LogMessage(level = INFO)
+	@Message(value = "Query plan cache misses: %s", id = 493)
+	void queryPlanCacheMisses(long queryPlanCacheMissCount);
 }

hibernate-core/src/main/java/org/hibernate/stat/QueryStatistics.java

@@ -75,4 +75,28 @@ public interface QueryStatistics extends Serializable {
 	 * sum total across all of those regions
 	 */
 	long getCachePutCount();
+
+	/**
+	 * The number of query plans successfully fetched from the cache.
+	 */
+	default long getPlanCacheHitCount() {
+		//For backward compatibility
+		return 0;
+	}
+
+	/**
+	 * The number of query plans *not* fetched from the cache.
+	 */
+	default long getPlanCacheMissCount(){
+		//For backward compatibility
+		return 0;
+	}
+
+	/**
+	 * The overall time spent to compile the plan for this particular query.
+	 */
+	default long getPlanCompilationTotalMicroseconds() {
+		//For backward compatibility
+		return 0;
+	}
 }

hibernate-core/src/main/java/org/hibernate/stat/Statistics.java

@@ -367,4 +367,20 @@ public interface Statistics {
 	 */
 	@Deprecated
 	NaturalIdCacheStatistics getNaturalIdCacheStatistics(String regionName);
+
+	/**
+	 * Get the global number of query plans successfully retrieved from cache
+	 */
+	default long getQueryPlanCacheHitCount() {
+		//For backward compatibility
+		return 0;
+	}
+
+	/**
+	 * Get the global number of query plans lookups *not* found in cache
+	 */
+	default long getQueryPlanCacheMissCount() {
+		//For backward compatibility
+		return 0;
+	}
 }

hibernate-core/src/main/java/org/hibernate/stat/internal/QueryStatisticsImpl.java

@@ -37,6 +37,11 @@ public class QueryStatisticsImpl implements QueryStatistics {
 	private final AtomicLong executionMinTime = new AtomicLong(Long.MAX_VALUE);
 	private final AtomicLong totalExecutionTime = new AtomicLong();
 
+	private final LongAdder planCacheHitCount = new LongAdder();
+	private final LongAdder planCacheMissCount = new LongAdder();
+	private final AtomicLong planCompilationTotalMicroseconds = new AtomicLong();
+
+
 	private final Lock readLock;
 	private final Lock writeLock;
 
@@ -131,6 +136,27 @@ public class QueryStatisticsImpl implements QueryStatistics {
 		return totalExecutionTime.get();
 	}
 
+	/**
+	 * Query plan successfully fetched from the cache
+	 */
+	public long getPlanCacheHitCount() {
+		return planCacheHitCount.sum();
+	}
+
+	/**
+	 * Query plan not fetched from the cache
+	 */
+	public long getPlanCacheMissCount() {
+		return planCacheMissCount.sum();
+	}
+
+	/**
+	 * Query plan overall compiled total
+	 */
+	public long getPlanCompilationTotalMicroseconds() {
+		return planCompilationTotalMicroseconds.get();
+	}
+
 	/**
 	 * add statistics report of a DB query
 	 *
@@ -156,6 +182,16 @@ public class QueryStatisticsImpl implements QueryStatistics {
 		}
 	}
 
+	/**
+	 * add plan statistics report of a DB query
+	 *
+	 * @param microseconds time taken
+	 */
+	void compiled(long microseconds) {
+		planCacheMissCount.increment();
+		planCompilationTotalMicroseconds.addAndGet( microseconds );
+	}
+
 	void incrementCacheHitCount() {
 		log.tracef( "QueryStatistics - cache hit : %s", query );
 
@@ -174,12 +210,18 @@ public class QueryStatisticsImpl implements QueryStatistics {
 		cachePutCount.increment();
 	}
 
+	void incrementPlanCacheHitCount() {
+		planCacheHitCount.increment();
+	}
+
 	public String toString() {
 		return "QueryStatistics"
 				+ "[query=" + query
 				+ ",cacheHitCount=" + this.cacheHitCount
 				+ ",cacheMissCount=" + this.cacheMissCount
 				+ ",cachePutCount=" + this.cachePutCount
+				+ ",planCacheHitCount=" + this.planCacheHitCount
+				+ ",planCacheMissCount=" + this.planCacheMissCount
 				+ ",executionCount=" + this.executionCount
 				+ ",executionRowCount=" + this.executionRowCount
 				+ ",executionAvgTime=" + this.getExecutionAvgTime()

hibernate-core/src/main/java/org/hibernate/stat/internal/StatisticsImpl.java

@@ -78,6 +78,9 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 	private final LongAdder queryCacheMissCount = new LongAdder();
 	private final LongAdder queryCachePutCount = new LongAdder();
 
+	private final LongAdder queryPlanCacheHitCount = new LongAdder();
+	private final LongAdder queryPlanCacheMissCount = new LongAdder();
+
 	private final LongAdder updateTimestampsCacheHitCount = new LongAdder();
 	private final LongAdder updateTimestampsCacheMissCount = new LongAdder();
 	private final LongAdder updateTimestampsCachePutCount = new LongAdder();
@@ -180,6 +183,9 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 		queryStatsMap.clear();
 		deprecatedNaturalIdStatsMap.clear();
 
+		queryPlanCacheHitCount.reset();
+		queryPlanCacheMissCount.reset();
+
 		startTime = System.currentTimeMillis();
 	}
 
@@ -782,13 +788,6 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 		}
 	}
 
-	private CacheRegionStatisticsImpl getQueryRegionStats(String regionName) {
-		return l2CacheStatsMap.computeIfAbsent(
-				regionName,
-				s -> new CacheRegionStatisticsImpl( sessionFactory.getCache().getQueryResultsCache( regionName ).getRegion() )
-		);
-	}
-
 
 	@Override
 	public void queryCacheMiss(String hql, String regionName) {
@@ -816,7 +815,40 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 		}
 	}
 
+	@Override
+	public long getQueryPlanCacheHitCount() {
+		return queryPlanCacheHitCount.sum();
+	}
 
+	@Override
+	public long getQueryPlanCacheMissCount() {
+		return queryPlanCacheMissCount.sum();
+	}
+
+	@Override
+	public void queryCompiled(String hql, long microseconds) {
+		queryPlanCacheMissCount.increment();
+
+		if ( hql != null ) {
+			getQueryStatistics( hql ).compiled( microseconds );
+		}
+	}
+
+	@Override
+	public void queryPlanCacheHit(String hql) {
+		queryPlanCacheHitCount.increment();
+
+		if ( hql != null ) {
+			getQueryStatistics( hql ).incrementPlanCacheHitCount();
+		}
+	}
+
+	private CacheRegionStatisticsImpl getQueryRegionStats(String regionName) {
+		return l2CacheStatsMap.computeIfAbsent(
+				regionName,
+				s -> new CacheRegionStatisticsImpl( sessionFactory.getCache().getQueryResultsCache( regionName ).getRegion() )
+		);
+	}
 
 	// ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 	// Session/misc stats
@@ -940,6 +972,8 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 		LOG.queryCacheHits( queryCacheHitCount.sum() );
 		LOG.queryCacheMisses( queryCacheMissCount.sum() );
 		LOG.maxQueryTime( queryExecutionMaxTime.get() );
+		LOG.queryPlanCacheHits( queryPlanCacheHitCount.sum() );
+		LOG.queryPlanCacheMisses( queryPlanCacheMissCount.sum() );
 	}
 
 	@Override
@@ -982,6 +1016,8 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 				.append(",update timestamps cache hits=").append(updateTimestampsCacheHitCount)
 				.append(",update timestamps cache misses=").append(updateTimestampsCacheMissCount)
 				.append( ",max query time=" ).append( queryExecutionMaxTime )
+				.append( ",query plan cache hits=" ).append( queryPlanCacheHitCount )
+				.append( ",query plan cache misses=" ).append( queryPlanCacheMissCount )
 				.append( ']' )
 				.toString();
 	}

hibernate-core/src/main/java/org/hibernate/stat/spi/StatisticsImplementor.java

@@ -135,9 +135,6 @@ public interface StatisticsImplementor extends Statistics, Service {
 	 */
 	void removeCollection(String role);
 
-
-
-
 	/**
 	 * Callback indicating a put into second level cache.
 	 *
@@ -159,9 +156,6 @@ public interface StatisticsImplementor extends Statistics, Service {
 	 */
 	void entityCacheMiss(NavigableRole entityName, String regionName);
 
-
-
-
 	/**
 	 * Callback indicating a put into second level cache.
 	 *
@@ -186,11 +180,6 @@ public interface StatisticsImplementor extends Statistics, Service {
 	 */
 	void collectionCacheMiss(NavigableRole collectionRole, String regionName);
 
-
-
-
-
-
 	/**
 	 * Callback indicating a put into natural id cache.
 	 */
@@ -211,9 +200,6 @@ public interface StatisticsImplementor extends Statistics, Service {
 	 */
 	void naturalIdQueryExecuted(String rootEntityName, long executionTime);
 
-
-
-
 	/**
 	 * Callback indicating a put into the query cache.
 	 *
@@ -247,7 +233,6 @@ public interface StatisticsImplementor extends Statistics, Service {
 	 */
 	void queryExecuted(String hql, int rows, long time);
 
-
 	/**
 	 * Callback indicating a hit to the timestamp cache
 	 */
@@ -262,4 +247,23 @@ public interface StatisticsImplementor extends Statistics, Service {
 	 * Callback indicating a put to the timestamp cache
 	 */
 	void updateTimestampsCachePut();
+
+	/**
+	 * Callback indicating a get from the query plan cache resulted in a hit.
+	 *
+	 * @param hql The query
+	 */
+	default void queryPlanCacheHit(String hql) {
+		//For backward compatibility
+	}
+
+	/**
+	 * Callback indicating compilation of a sql/hql query
+	 *
+	 * @param hql The query
+	 * @param microseconds execution time
+	 */
+	default void queryCompiled(String hql, long microseconds) {
+		//For backward compatibility
+	}
 }

hibernate-core/src/test/java/org/hibernate/stat/internal/ConcurrentQueryStatisticsTest.java

@@ -12,8 +12,6 @@ import org.junit.Test;
 import static org.junit.Assert.assertEquals;
 
 /**
- * <code>ConcurrentQueryStatisticsTest</code> -
- *
  * @author Vlad Mihalcea
  */
 public class ConcurrentQueryStatisticsTest extends BaseUnitTestCase {

hibernate-core/src/test/java/org/hibernate/stat/internal/QueryPlanCacheStatisticsTest.java

@@ -0,0 +1,153 @@
+/*
+ * Hibernate, Relational Persistence for Idiomatic Java
+ *
+ * License: GNU Lesser General Public License (LGPL), version 2.1 or later.
+ * See the lgpl.txt file in the root directory or <http://www.gnu.org/licenses/lgpl-2.1.html>.
+ */
+package org.hibernate.stat.internal;
+
+import java.util.Map;
+import javax.persistence.Entity;
+import javax.persistence.GeneratedValue;
+import javax.persistence.Id;
+
+import org.hibernate.SessionFactory;
+import org.hibernate.cfg.Environment;
+import org.hibernate.jpa.test.BaseEntityManagerFunctionalTestCase;
+import org.hibernate.stat.QueryStatistics;
+import org.hibernate.stat.Statistics;
+
+import org.hibernate.testing.TestForIssue;
+import org.junit.Test;
+
+import static org.hibernate.testing.transaction.TransactionUtil.doInJPA;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertTrue;
+
+/**
+ * @author Gail Badner
+ */
+@TestForIssue(jiraKey = "HHH-12855")
+public class QueryPlanCacheStatisticsTest extends BaseEntityManagerFunctionalTestCase {
+
+	private Statistics statistics;
+
+	@Override
+	public Class[] getAnnotatedClasses() {
+		return new Class[] {
+				Employee.class
+		};
+	}
+
+	protected void addConfigOptions(Map options) {
+		options.put( Environment.GENERATE_STATISTICS, "true" );
+	}
+
+	@Override
+	protected void afterEntityManagerFactoryBuilt() {
+		SessionFactory sessionFactory = entityManagerFactory().unwrap( SessionFactory.class );
+		statistics = sessionFactory.getStatistics();
+
+		doInJPA( this::entityManagerFactory, entityManager -> {
+			for ( long i = 1; i <= 5; i++ ) {
+				if ( i % 3 == 0 ) {
+					entityManager.flush();
+				}
+				Employee employee = new Employee();
+				employee.setName( String.format( "Employee: %d", i ) );
+				entityManager.persist( employee );
+			}
+		} );
+	}
+
+	@Test
+	public void test() {
+
+		assertEquals( 0, statistics.getQueryPlanCacheHitCount() );
+		assertEquals( 0, statistics.getQueryPlanCacheMissCount() );
+
+		doInJPA( this::entityManagerFactory, entityManager -> {
+			final String FIRST_QUERY = "select e from Employee e";
+
+			entityManager.createQuery( FIRST_QUERY );
+
+			assertEquals( 0, statistics.getQueryPlanCacheHitCount() );
+			assertEquals( 1, statistics.getQueryPlanCacheMissCount() );
+
+			assertQueryStatistics( FIRST_QUERY, 0 );
+
+			entityManager.createQuery( FIRST_QUERY );
+
+			assertEquals( 1, statistics.getQueryPlanCacheHitCount() );
+			assertEquals( 1, statistics.getQueryPlanCacheMissCount() );
+
+			assertQueryStatistics( FIRST_QUERY, 1 );
+
+			entityManager.createQuery( FIRST_QUERY );
+
+			assertEquals( 2, statistics.getQueryPlanCacheHitCount() );
+			assertEquals( 1, statistics.getQueryPlanCacheMissCount() );
+
+			assertQueryStatistics( FIRST_QUERY, 2 );
+
+			final String SECOND_QUERY = "select count(e) from Employee e";
+
+			entityManager.createQuery( SECOND_QUERY );
+
+			assertEquals( 2, statistics.getQueryPlanCacheHitCount() );
+			assertEquals( 2, statistics.getQueryPlanCacheMissCount() );
+
+			assertQueryStatistics( SECOND_QUERY, 0 );
+
+			entityManager.createQuery( SECOND_QUERY );
+
+			assertEquals( 3, statistics.getQueryPlanCacheHitCount() );
+			assertEquals( 2, statistics.getQueryPlanCacheMissCount() );
+
+			assertQueryStatistics( SECOND_QUERY, 1 );
+
+			entityManager.createQuery( SECOND_QUERY );
+
+			assertEquals( 4, statistics.getQueryPlanCacheHitCount() );
+			assertEquals( 2, statistics.getQueryPlanCacheMissCount() );
+
+			assertQueryStatistics( SECOND_QUERY, 2 );
+		} );
+	}
+
+	private void assertQueryStatistics(String hql, int hitCount) {
+		QueryStatistics queryStatistics = statistics.getQueryStatistics( hql );
+
+		assertEquals( hitCount, queryStatistics.getPlanCacheHitCount() );
+		assertEquals( 1, queryStatistics.getPlanCacheMissCount() );
+
+		assertTrue( queryStatistics.getPlanCompilationTotalMicroseconds() > 0 );
+	}
+
+	@Entity(name = "Employee")
+	public static class Employee {
+
+		@Id
+		@GeneratedValue
+		private Long id;
+
+		private String name;
+
+		public Long getId() {
+			return id;
+		}
+
+		public void setId(Long id) {
+			this.id = id;
+		}
+
+		public String getName() {
+			return name;
+		}
+
+		public void setName(String name) {
+			this.name = name;
+		}
+	}
+
+}