Log context cache statistics in the TCF

Prior to this commit, finding out how many application contexts had
been loaded within a test suite required the use of reflection and a
bit of hacking.

This commit addresses this issue by logging ContextCache statistics
whenever an application context is loaded by the Spring TestContext
Framework (TCF).

The log output can be enabled by setting the
"org.springframework.test.context.cache" logging category to DEBUG.

Issue: SPR-12409

Author: sbrannen

spring-test/src/main/java/org/springframework/test/context/ContextCache.java

@@ -1,5 +1,5 @@
 /*
- * Copyright 2002-2013 the original author or authors.
+ * Copyright 2002-2014 the original author or authors.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -22,6 +22,7 @@
 import java.util.Map;
 import java.util.Set;
 import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.atomic.AtomicInteger;
 
 import org.springframework.context.ApplicationContext;
 import org.springframework.context.ConfigurableApplicationContext;
@@ -64,9 +65,9 @@ class ContextCache {
 	private final Map<MergedContextConfiguration, Set<MergedContextConfiguration>> hierarchyMap = new ConcurrentHashMap<MergedContextConfiguration, Set<MergedContextConfiguration>>(
 		64);
 
-	private int hitCount;
+	private final AtomicInteger hitCount = new AtomicInteger();
 
-	private int missCount;
+	private final AtomicInteger missCount = new AtomicInteger();
 
 
 	/**
@@ -84,8 +85,8 @@ void clear() {
 	 * Clears hit and miss count statistics for the cache (i.e., resets counters to zero).
 	 */
 	void clearStatistics() {
-		this.hitCount = 0;
-		this.missCount = 0;
+		this.hitCount.set(0);
+		this.missCount.set(0);
 	}
 
 	/**
@@ -116,45 +117,31 @@ ApplicationContext get(MergedContextConfiguration key) {
 		synchronized (monitor) {
 			ApplicationContext context = this.contextMap.get(key);
 			if (context == null) {
-				incrementMissCount();
+				this.missCount.incrementAndGet();
 			}
 			else {
-				incrementHitCount();
+				this.hitCount.incrementAndGet();
 			}
 			return context;
 		}
 	}
 
 	/**
-	 * Increment the hit count by one. A <em>hit</em> is an access to the cache, which
-	 * returned a non-null context for a queried key.
-	 */
-	private void incrementHitCount() {
-		this.hitCount++;
-	}
-
-	/**
-	 * Increment the miss count by one. A <em>miss</em> is an access to the cache, which
-	 * returned a {@code null} context for a queried key.
-	 */
-	private void incrementMissCount() {
-		this.missCount++;
-	}
-
-	/**
-	 * Get the overall hit count for this cache. A <em>hit</em> is an access to the cache,
-	 * which returned a non-null context for a queried key.
+	 * Get the overall hit count for this cache.
+	 * <p>A <em>hit</em> is an access to the cache, which returned a non-null context for
+	 * a queried key.
 	 */
 	int getHitCount() {
-		return this.hitCount;
+		return this.hitCount.get();
 	}
 
 	/**
-	 * Get the overall miss count for this cache. A <em>miss</em> is an access to the
-	 * cache, which returned a {@code null} context for a queried key.
+	 * Get the overall miss count for this cache.
+	 * <p>A <em>miss</em> is an access to the cache, which returned a {@code null} context
+	 * for a queried key.
 	 */
 	int getMissCount() {
-		return this.missCount;
+		return this.missCount.get();
 	}
 
 	/**

spring-test/src/main/java/org/springframework/test/context/DefaultCacheAwareContextLoaderDelegate.java

@@ -38,6 +38,8 @@ class DefaultCacheAwareContextLoaderDelegate implements CacheAwareContextLoaderD
 
 	private static final Log logger = LogFactory.getLog(DefaultCacheAwareContextLoaderDelegate.class);
 
+	private static final Log statsLogger = LogFactory.getLog("org.springframework.test.context.cache");
+
 	private final ContextCache contextCache;
 
 
@@ -98,6 +100,11 @@ public ApplicationContext loadContext(MergedContextConfiguration mergedContextCo
 						mergedContextConfiguration));
 				}
 			}
+
+			if (statsLogger.isDebugEnabled()) {
+				statsLogger.debug(String.format("Spring test ApplicationContext cache statistics: %s", contextCache));
+			}
+
 			return context;
 		}
 	}

spring-test/src/test/resources/log4j.properties

@@ -15,6 +15,7 @@ log4j.logger.org.springframework.test.context.ContextLoaderUtils=WARN
 log4j.logger.org.springframework.test.context.transaction.TransactionalTestExecutionListener=WARN
 log4j.logger.org.springframework.test.context.web=WARN
 log4j.logger.org.springframework.test.context=WARN
+log4j.logger.org.springframework.test.context.cache=WARN
 
 #log4j.logger.org.springframework.test.context.support=INFO
 #log4j.logger.org.springframework.test.context.support.DelegatingSmartContextLoader=INFO

src/asciidoc/index.adoc

@@ -20851,6 +20851,12 @@ framework will not be able to cache application contexts between test classes an
 build process will run significantly slower as a result.
 ====
 
+Since having a large number of application contexts loaded within a given test suite can
+cause the suite to take an unnecessarily long time to execute, it is often beneficial to
+know exactly how many contexts have been loaded and cached. To view the statistics for
+the underlying context cache, simply set the log level for the
+`org.springframework.test.context.cache` logging category to `DEBUG`.
+
 In the unlikely case that a test corrupts the application context and requires reloading
 -- for example, by modifying a bean definition or the state of an application object --
 you can annotate your test class or test method with `@DirtiesContext` (see the
@@ -20860,6 +20866,7 @@ context before executing the next test. Note that support for the `@DirtiesConte
 annotation is provided by the `DirtiesContextTestExecutionListener` which is enabled by
 default.
 
+
 [[testcontext-ctx-management-ctx-hierarchies]]
 ====== Context hierarchies