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
(cherry picked from commit da04362)

spring-test/src/main/java/org/springframework/test/context/CacheAwareContextLoaderDelegate.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.
@@ -18,6 +18,7 @@ package org.springframework.test.context;
 
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
+
 import org.springframework.context.ApplicationContext;
 import org.springframework.util.Assert;
 
@@ -37,6 +38,8 @@ public class CacheAwareContextLoaderDelegate {
 
 	private static final Log logger = LogFactory.getLog(CacheAwareContextLoaderDelegate.class);
 
+	private static final Log statsLogger = LogFactory.getLog("org.springframework.test.context.cache");
+
 	private final ContextCache contextCache;
 
 
@@ -45,6 +48,7 @@ public class CacheAwareContextLoaderDelegate {
 		this.contextCache = contextCache;
 	}
 
+
 	/**
 	 * Load the {@code ApplicationContext} for the supplied merged context
 	 * configuration. Supports both the {@link SmartContextLoader} and
@@ -53,9 +57,10 @@ public class CacheAwareContextLoaderDelegate {
 	 */
 	private ApplicationContext loadContextInternal(MergedContextConfiguration mergedContextConfiguration)
 			throws Exception {
+
 		ContextLoader contextLoader = mergedContextConfiguration.getContextLoader();
-		Assert.notNull(contextLoader, "Cannot load an ApplicationContext with a NULL 'contextLoader'. "
-				+ "Consider annotating your test class with @ContextConfiguration or @ContextHierarchy.");
+		Assert.notNull(contextLoader, "Cannot load an ApplicationContext with a NULL 'contextLoader'. " +
+				"Consider annotating your test class with @ContextConfiguration or @ContextHierarchy.");
 
 		ApplicationContext applicationContext;
 
@@ -65,8 +70,8 @@ public class CacheAwareContextLoaderDelegate {
 		}
 		else {
 			String[] locations = mergedContextConfiguration.getLocations();
-			Assert.notNull(locations, "Cannot load an ApplicationContext with a NULL 'locations' array. "
-					+ "Consider annotating your test class with @ContextConfiguration or @ContextHierarchy.");
+			Assert.notNull(locations, "Cannot load an ApplicationContext with a NULL 'locations' array. " +
+					"Consider annotating your test class with @ContextConfiguration or @ContextHierarchy.");
 			applicationContext = contextLoader.loadContext(locations);
 		}
 
@@ -76,7 +81,6 @@ public class CacheAwareContextLoaderDelegate {
 	/**
 	 * Load the {@link ApplicationContext application context} for the supplied
 	 * merged context configuration.
-	 *
 	 * <p>If the context is present in the cache it will simply be returned;
 	 * otherwise, it will be loaded, stored in the cache, and returned.
 	 * @return the application context
@@ -84,16 +88,16 @@ public class CacheAwareContextLoaderDelegate {
 	 * loading the application context
 	 */
 	public ApplicationContext loadContext(MergedContextConfiguration mergedContextConfiguration) {
-		synchronized (contextCache) {
-			ApplicationContext context = contextCache.get(mergedContextConfiguration);
+		synchronized (this.contextCache) {
+			ApplicationContext context = this.contextCache.get(mergedContextConfiguration);
 			if (context == null) {
 				try {
 					context = loadContextInternal(mergedContextConfiguration);
 					if (logger.isDebugEnabled()) {
-						logger.debug(String.format("Storing ApplicationContext in cache under key [%s].",
-							mergedContextConfiguration));
+						logger.debug(String.format("Storing ApplicationContext in cache under key [%s]",
+								mergedContextConfiguration));
 					}
-					contextCache.put(mergedContextConfiguration, context);
+					this.contextCache.put(mergedContextConfiguration, context);
 				}
 				catch (Exception ex) {
 					throw new IllegalStateException("Failed to load ApplicationContext", ex);
@@ -101,10 +105,15 @@ public class CacheAwareContextLoaderDelegate {
 			}
 			else {
 				if (logger.isDebugEnabled()) {
-					logger.debug(String.format("Retrieved ApplicationContext from cache with key [%s].",
-						mergedContextConfiguration));
+					logger.debug(String.format("Retrieved ApplicationContext from cache with key [%s]",
+							mergedContextConfiguration));
 				}
 			}
+
+			if (statsLogger.isDebugEnabled()) {
+				statsLogger.debug("Spring test ApplicationContext cache statistics: " + this.contextCache);
+			}
+
 			return context;
 		}
 	}

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.List;
 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;
@@ -47,13 +48,11 @@ import org.springframework.util.Assert;
  */
 class ContextCache {
 
-	private final Object monitor = new Object();
-
 	/**
 	 * Map of context keys to Spring {@code ApplicationContext} instances.
 	 */
-	private final Map<MergedContextConfiguration, ApplicationContext> contextMap = new ConcurrentHashMap<MergedContextConfiguration, ApplicationContext>(
-		64);
+	private final Map<MergedContextConfiguration, ApplicationContext> contextMap =
+			new ConcurrentHashMap<MergedContextConfiguration, ApplicationContext>(64);
 
 	/**
 	 * Map of parent keys to sets of children keys, representing a top-down <em>tree</em>
@@ -61,128 +60,99 @@ class ContextCache {
 	 * need to be recursively removed and closed when removing a context that is a parent
 	 * of other contexts.
 	 */
-	private final Map<MergedContextConfiguration, Set<MergedContextConfiguration>> hierarchyMap = new ConcurrentHashMap<MergedContextConfiguration, Set<MergedContextConfiguration>>(
-		64);
+	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();
 
 
 	/**
-	 * Clears all contexts from the cache and clears context hierarchy information as
-	 * well.
+	 * Clear all contexts from the cache and clears context hierarchy information as well.
 	 */
-	void clear() {
-		synchronized (monitor) {
-			this.contextMap.clear();
-			this.hierarchyMap.clear();
-		}
+	public void clear() {
+		this.contextMap.clear();
+		this.hierarchyMap.clear();
 	}
 
 	/**
-	 * Clears hit and miss count statistics for the cache (i.e., resets counters to zero).
+	 * Clear hit and miss count statistics for the cache (i.e., resets counters to zero).
 	 */
-	void clearStatistics() {
-		this.hitCount = 0;
-		this.missCount = 0;
+	public void clearStatistics() {
+		this.hitCount.set(0);
+		this.missCount.set(0);
 	}
 
 	/**
 	 * Return whether there is a cached context for the given key.
-	 *
 	 * @param key the context key (never {@code null})
 	 */
-	boolean contains(MergedContextConfiguration key) {
+	public boolean contains(MergedContextConfiguration key) {
 		Assert.notNull(key, "Key must not be null");
-		synchronized (monitor) {
-			return this.contextMap.containsKey(key);
-		}
+		return this.contextMap.containsKey(key);
 	}
 
 	/**
 	 * Obtain a cached {@code ApplicationContext} for the given key.
-	 *
-	 * <p>The {@link #getHitCount() hit} and {@link #getMissCount() miss} counts will be
-	 * updated accordingly.
-	 *
+	 * <p>The {@link #getHitCount() hit} and {@link #getMissCount() miss} counts will
+	 * be updated accordingly.
 	 * @param key the context key (never {@code null})
-	 * @return the corresponding {@code ApplicationContext} instance, or {@code null} if
-	 * not found in the cache.
+	 * @return the corresponding {@code ApplicationContext} instance, or {@code null}
+	 * if not found in the cache
 	 * @see #remove
 	 */
-	ApplicationContext get(MergedContextConfiguration key) {
+	public ApplicationContext get(MergedContextConfiguration key) {
 		Assert.notNull(key, "Key must not be null");
-		synchronized (monitor) {
-			ApplicationContext context = this.contextMap.get(key);
-			if (context == null) {
-				incrementMissCount();
-			}
-			else {
-				incrementHitCount();
-			}
-			return context;
+		ApplicationContext context = this.contextMap.get(key);
+		if (context == null) {
+			this.missCount.incrementAndGet();
 		}
+		else {
+			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;
+	public int getHitCount() {
+		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;
+	public int getMissCount() {
+		return this.missCount.get();
 	}
 
 	/**
-	 * Explicitly add an {@code ApplicationContext} instance to the cache under the given
-	 * key.
-	 *
+	 * Explicitly add an {@code ApplicationContext} instance to the cache under the given key.
 	 * @param key the context key (never {@code null})
 	 * @param context the {@code ApplicationContext} instance (never {@code null})
 	 */
-	void put(MergedContextConfiguration key, ApplicationContext context) {
+	public void put(MergedContextConfiguration key, ApplicationContext context) {
 		Assert.notNull(key, "Key must not be null");
 		Assert.notNull(context, "ApplicationContext must not be null");
 
-		synchronized (monitor) {
-			this.contextMap.put(key, context);
-
-			MergedContextConfiguration child = key;
-			MergedContextConfiguration parent = child.getParent();
-			while (parent != null) {
-				Set<MergedContextConfiguration> list = hierarchyMap.get(parent);
-				if (list == null) {
-					list = new HashSet<MergedContextConfiguration>();
-					hierarchyMap.put(parent, list);
-				}
-				list.add(child);
-				child = parent;
-				parent = child.getParent();
+		this.contextMap.put(key, context);
+		MergedContextConfiguration child = key;
+		MergedContextConfiguration parent = child.getParent();
+		while (parent != null) {
+			Set<MergedContextConfiguration> list = this.hierarchyMap.get(parent);
+			if (list == null) {
+				list = new HashSet<MergedContextConfiguration>();
+				this.hierarchyMap.put(parent, list);
 			}
+			list.add(child);
+			child = parent;
+			parent = child.getParent();
 		}
 	}
 
@@ -190,19 +160,16 @@ class ContextCache {
 	 * Remove the context with the given key from the cache and explicitly
 	 * {@linkplain ConfigurableApplicationContext#close() close} it if it is an
 	 * instance of {@link ConfigurableApplicationContext}.
-	 *
 	 * <p>Generally speaking, you would only call this method if you change the
 	 * state of a singleton bean, potentially affecting future interaction with
 	 * the context.
-	 *
 	 * <p>In addition, the semantics of the supplied {@code HierarchyMode} will
 	 * be honored. See the Javadoc for {@link HierarchyMode} for details.
-	 *
 	 * @param key the context key; never {@code null}
 	 * @param hierarchyMode the hierarchy mode; may be {@code null} if the context
 	 * is not part of a hierarchy
 	 */
-	void remove(MergedContextConfiguration key, HierarchyMode hierarchyMode) {
+	public void remove(MergedContextConfiguration key, HierarchyMode hierarchyMode) {
 		Assert.notNull(key, "Key must not be null");
 
 		// startKey is the level at which to begin clearing the cache, depending
@@ -214,24 +181,21 @@ class ContextCache {
 			}
 		}
 
-		synchronized (monitor) {
-			final List<MergedContextConfiguration> removedContexts = new ArrayList<MergedContextConfiguration>();
-
-			remove(removedContexts, startKey);
+		List<MergedContextConfiguration> removedContexts = new ArrayList<MergedContextConfiguration>();
+		remove(removedContexts, startKey);
 
-			// Remove all remaining references to any removed contexts from the
-			// hierarchy map.
-			for (MergedContextConfiguration currentKey : removedContexts) {
-				for (Set<MergedContextConfiguration> children : hierarchyMap.values()) {
-					children.remove(currentKey);
-				}
+		// Remove all remaining references to any removed contexts from the
+		// hierarchy map.
+		for (MergedContextConfiguration currentKey : removedContexts) {
+			for (Set<MergedContextConfiguration> children : this.hierarchyMap.values()) {
+				children.remove(currentKey);
 			}
+		}
 
-			// Remove empty entries from the hierarchy map.
-			for (MergedContextConfiguration currentKey : hierarchyMap.keySet()) {
-				if (hierarchyMap.get(currentKey).isEmpty()) {
-					hierarchyMap.remove(currentKey);
-				}
+		// Remove empty entries from the hierarchy map.
+		for (MergedContextConfiguration currentKey : this.hierarchyMap.keySet()) {
+			if (this.hierarchyMap.get(currentKey).isEmpty()) {
+				this.hierarchyMap.remove(currentKey);
 			}
 		}
 	}
@@ -239,26 +203,23 @@ class ContextCache {
 	private void remove(List<MergedContextConfiguration> removedContexts, MergedContextConfiguration key) {
 		Assert.notNull(key, "Key must not be null");
 
-		synchronized (monitor) {
-			Set<MergedContextConfiguration> children = hierarchyMap.get(key);
-			if (children != null) {
-				for (MergedContextConfiguration child : children) {
-					// Recurse through lower levels
-					remove(removedContexts, child);
-				}
-				// Remove the set of children for the current context from the
-				// hierarchy map.
-				hierarchyMap.remove(key);
+		Set<MergedContextConfiguration> children = this.hierarchyMap.get(key);
+		if (children != null) {
+			for (MergedContextConfiguration child : children) {
+				// Recurse through lower levels
+				remove(removedContexts, child);
 			}
+			// Remove the set of children for the current context from the hierarchy map.
+			this.hierarchyMap.remove(key);
+		}
 
-			// Physically remove and close leaf nodes first (i.e., on the way back up the
-			// stack as opposed to prior to the recursive call).
-			ApplicationContext context = contextMap.remove(key);
-			if (context instanceof ConfigurableApplicationContext) {
-				((ConfigurableApplicationContext) context).close();
-			}
-			removedContexts.add(key);
+		// Physically remove and close leaf nodes first (i.e., on the way back up the
+		// stack as opposed to prior to the recursive call).
+		ApplicationContext context = this.contextMap.remove(key);
+		if (context instanceof ConfigurableApplicationContext) {
+			((ConfigurableApplicationContext) context).close();
 		}
+		removedContexts.add(key);
 	}
 
 	/**
@@ -266,34 +227,30 @@ class ContextCache {
 	 * contains more than <tt>Integer.MAX_VALUE</tt> elements, returns
 	 * <tt>Integer.MAX_VALUE</tt>.
 	 */
-	int size() {
-		synchronized (monitor) {
-			return this.contextMap.size();
-		}
+	public int size() {
+		return this.contextMap.size();
 	}
 
 	/**
 	 * Determine the number of parent contexts currently tracked within the cache.
 	 */
-	int getParentContextCount() {
-		synchronized (monitor) {
-			return this.hierarchyMap.size();
-		}
+	public int getParentContextCount() {
+		return this.hierarchyMap.size();
 	}
 
 	/**
 	 * Generates a text string, which contains the {@linkplain #size() size} as well
-	 * as the {@linkplain #getHitCount() hit}, {@linkplain #getMissCount() miss}, and
-	 * {@linkplain #getParentContextCount() parent context} counts.
+	 * as the {@linkplain #getHitCount() hit}, {@linkplain #getMissCount() miss},
+	 * and {@linkplain #getParentContextCount() parent context} counts.
 	 */
 	@Override
 	public String toString() {
-		return new ToStringCreator(this)//
-		.append("size", size())//
-		.append("hitCount", getHitCount())//
-		.append("missCount", getMissCount())//
-		.append("parentContextCount", getParentContextCount())//
-		.toString();
+		return new ToStringCreator(this)
+				.append("size", size())
+				.append("hitCount", getHitCount())
+				.append("missCount", getMissCount())
+				.append("parentContextCount", getParentContextCount())
+				.toString();
 	}
 
 }

spring-test/src/main/java/org/springframework/test/context/DefaultTestContext.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.
@@ -78,8 +78,7 @@ class DefaultTestContext extends AttributeAccessorSupport implements TestContext
 	 * @param testClass the test class for which the test context should be
 	 * constructed (must not be {@code null})
 	 * @param contextCache the context cache from which the constructed test
-	 * context should retrieve application contexts (must not be
-	 * {@code null})
+	 * context should retrieve application contexts (must not be {@code null})
 	 * @param defaultContextLoaderClassName the name of the default
 	 * {@code ContextLoader} class to use (may be {@code null})
 	 */
@@ -90,73 +89,56 @@ class DefaultTestContext extends AttributeAccessorSupport implements TestContext
 		this.testClass = testClass;
 		this.contextCache = contextCache;
 		this.cacheAwareContextLoaderDelegate = new CacheAwareContextLoaderDelegate(contextCache);
-		this.mergedContextConfiguration = ContextLoaderUtils.buildMergedContextConfiguration(testClass,
-			defaultContextLoaderClassName, cacheAwareContextLoaderDelegate);
+		this.mergedContextConfiguration = ContextLoaderUtils.buildMergedContextConfiguration(
+				testClass, defaultContextLoaderClassName, this.cacheAwareContextLoaderDelegate);
 	}
 
-	/**
-	 * {@inheritDoc}
-	 */
+
 	public ApplicationContext getApplicationContext() {
-		return cacheAwareContextLoaderDelegate.loadContext(mergedContextConfiguration);
+		return this.cacheAwareContextLoaderDelegate.loadContext(this.mergedContextConfiguration);
 	}
 
-	/**
-	 * {@inheritDoc}
-	 */
 	public final Class<?> getTestClass() {
-		return testClass;
+		return this.testClass;
 	}
 
-	/**
-	 * {@inheritDoc}
-	 */
 	public final Object getTestInstance() {
-		return testInstance;
+		return this.testInstance;
 	}
 
-	/**
-	 * {@inheritDoc}
-	 */
 	public final Method getTestMethod() {
-		return testMethod;
+		return this.testMethod;
 	}
 
-	/**
-	 * {@inheritDoc}
-	 */
 	public final Throwable getTestException() {
-		return testException;
+		return this.testException;
 	}
 
-	/**
-	 * {@inheritDoc}
-	 */
 	public void markApplicationContextDirty(HierarchyMode hierarchyMode) {
-		contextCache.remove(mergedContextConfiguration, hierarchyMode);
+		synchronized (this.contextCache) {
+			this.contextCache.remove(this.mergedContextConfiguration, hierarchyMode);
+		}
 	}
 
-	/**
-	 * {@inheritDoc}
-	 */
 	public void updateState(Object testInstance, Method testMethod, Throwable testException) {
 		this.testInstance = testInstance;
 		this.testMethod = testMethod;
 		this.testException = testException;
 	}
 
+
 	/**
 	 * Provide a String representation of this test context's state.
 	 */
 	@Override
 	public String toString() {
-		return new ToStringCreator(this)//
-		.append("testClass", testClass)//
-		.append("testInstance", testInstance)//
-		.append("testMethod", testMethod)//
-		.append("testException", testException)//
-		.append("mergedContextConfiguration", mergedContextConfiguration)//
-		.toString();
+		return new ToStringCreator(this)
+				.append("testClass", this.testClass)
+				.append("testInstance", this.testInstance)
+				.append("testMethod", this.testMethod)
+				.append("testException", this.testException)
+				.append("mergedContextConfiguration", this.mergedContextConfiguration)
+				.toString();
 	}
 
 }

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.DelegatingSmartContextLoader=INFO
 #log4j.logger.org.springframework.test.context.support.AbstractGenericContextLoader=INFO

src/asciidoc/index.adoc

@@ -19503,6 +19503,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
@@ -19512,6 +19518,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