Merge pull request #1261 from jamesagnew/ja_interceptor_jpa_queries

JPA Performance Interceptor Framework

hapi-deployable-pom/pom.xml

@@ -139,6 +139,10 @@
 							<groupId>org.apache.derby</groupId>
 							<artifactId>derbyclient</artifactId>
 						</dependency>
+						<dependency>
+							<groupId>org.checkerframework</groupId>
+							<artifactId>checker-compat-qual</artifactId>
+						</dependency>
 					</ignoredDependencies>
 					<ignoredResourcePatterns>
 						<ignoredResourcePattern>changelog.txt</ignoredResourcePattern>

hapi-fhir-base/src/main/java/ca/uhn/fhir/util/LogUtil.java

@@ -0,0 +1,35 @@
+package ca.uhn.fhir.util;
+
+import org.slf4j.Logger;
+import org.slf4j.event.Level;
+
+/**
+ * Utility to fill a glaring gap in SLF4j's API - The fact that you can't
+ * specify a log level at runtime.
+ *
+ * See here for a discussion:
+ * https://jira.qos.ch/browse/SLF4J-124
+ */
+public class LogUtil {
+
+	public static void log(Logger theLogger, Level theLevel, String theMessage, Object... theArgs) {
+		switch (theLevel) {
+			case TRACE:
+				theLogger.trace(theMessage, theArgs);
+				break;
+			case DEBUG:
+				theLogger.debug(theMessage, theArgs);
+				break;
+			case INFO:
+				theLogger.info(theMessage, theArgs);
+				break;
+			case WARN:
+				theLogger.warn(theMessage, theArgs);
+				break;
+			case ERROR:
+				theLogger.error(theMessage, theArgs);
+				break;
+		}
+	}
+
+}

hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java

@@ -7,7 +7,6 @@ import java.text.DecimalFormat;
 import java.text.NumberFormat;
 import java.util.Date;
 import java.util.LinkedList;
-import java.util.List;
 import java.util.concurrent.TimeUnit;
 
 import static org.apache.commons.lang3.StringUtils.isNotBlank;
@@ -45,20 +44,16 @@ import static org.apache.commons.lang3.StringUtils.isNotBlank;
  */
 public class StopWatch {
 
-	private static final NumberFormat DAY_FORMAT = new DecimalFormat("0.0");
-	private static final NumberFormat TEN_DAY_FORMAT = new DecimalFormat("0");
 	private static Long ourNowForUnitTest;
 	private long myStarted = now();
 	private TaskTiming myCurrentTask;
 	private LinkedList<TaskTiming> myTasks;
-
 	/**
 	 * Constructor
 	 */
 	public StopWatch() {
 		super();
 	}
-
 	/**
 	 * Constructor
 	 *
@@ -93,6 +88,19 @@ public class StopWatch {
 		}
 	}
 
+	/**
+	 * Returns a nice human-readable display of the time taken per
+	 * operation. Note that this may not actually output the number
+	 * of milliseconds if the time taken per operation was very long (over
+	 * 10 seconds)
+	 *
+	 * @see #formatMillis(long)
+	 */
+	public String formatMillisPerOperation(int theNumOperations) {
+		double millisPerOperation = (((double) getMillis()) / Math.max(1.0, theNumOperations));
+		return formatMillis(millisPerOperation);
+	}
+
 	/**
 	 * Returns a string providing the durations of all tasks collected by {@link #startTask(String)}
 	 */
@@ -261,77 +269,6 @@ public class StopWatch {
 		return formatMillis(getMillis());
 	}
 
-	/**
-	 * Append a right-aligned and zero-padded numeric value to a `StringBuilder`.
-	 */
-	static private void append(StringBuilder tgt, String pfx, int dgt, long val) {
-		tgt.append(pfx);
-		if (dgt > 1) {
-			int pad = (dgt - 1);
-			for (long xa = val; xa > 9 && pad > 0; xa /= 10) {
-				pad--;
-			}
-			for (int xa = 0; xa < pad; xa++) {
-				tgt.append('0');
-			}
-		}
-		tgt.append(val);
-	}
-
-	/**
-	 * Formats a number of milliseconds for display (e.g.
-	 * in a log file), tailoring the output to how big
-	 * the value actually is.
-	 * <p>
-	 * Example outputs:
-	 * </p>
-	 * <ul>
-	 * <li>133ms</li>
-	 * <li>00:00:10.223</li>
-	 * <li>1.7 days</li>
-	 * <li>64 days</li>
-	 * </ul>
-	 */
-	public static String formatMillis(long val) {
-		StringBuilder buf = new StringBuilder(20);
-		if (val < (10 * DateUtils.MILLIS_PER_SECOND)) {
-			buf.append(val);
-			buf.append("ms");
-		} else if (val >= DateUtils.MILLIS_PER_DAY) {
-			double days = (double) val / DateUtils.MILLIS_PER_DAY;
-			if (days >= 10) {
-				buf.append(TEN_DAY_FORMAT.format(days));
-				buf.append(" days");
-			} else if (days != 1.0f) {
-				buf.append(DAY_FORMAT.format(days));
-				buf.append(" days");
-			} else {
-				buf.append(DAY_FORMAT.format(days));
-				buf.append(" day");
-			}
-		} else {
-			append(buf, "", 2, ((val % DateUtils.MILLIS_PER_DAY) / DateUtils.MILLIS_PER_HOUR));
-			append(buf, ":", 2, ((val % DateUtils.MILLIS_PER_HOUR) / DateUtils.MILLIS_PER_MINUTE));
-			append(buf, ":", 2, ((val % DateUtils.MILLIS_PER_MINUTE) / DateUtils.MILLIS_PER_SECOND));
-			if (val <= DateUtils.MILLIS_PER_MINUTE) {
-				append(buf, ".", 3, (val % DateUtils.MILLIS_PER_SECOND));
-			}
-		}
-		return buf.toString();
-	}
-
-	private static long now() {
-		if (ourNowForUnitTest != null) {
-			return ourNowForUnitTest;
-		}
-		return System.currentTimeMillis();
-	}
-
-	@VisibleForTesting
-	static void setNowForUnitTestForUnitTest(Long theNowForUnitTest) {
-		ourNowForUnitTest = theNowForUnitTest;
-	}
-
 	private static class TaskTiming {
 		private long myStart;
 		private long myEnd;
@@ -372,4 +309,109 @@ public class StopWatch {
 		}
 	}
 
+	private static NumberFormat getDayFormat() {
+		return new DecimalFormat("0.0");
+	}
+
+	private static NumberFormat getTenDayFormat() {
+		return new DecimalFormat("0");
+	}
+
+	private static NumberFormat getSubMillisecondMillisFormat() {
+		return new DecimalFormat("0.000");
+	}
+
+	/**
+	 * Append a right-aligned and zero-padded numeric value to a `StringBuilder`.
+	 */
+	static private void append(StringBuilder tgt, String pfx, int dgt, long val) {
+		tgt.append(pfx);
+		if (dgt > 1) {
+			int pad = (dgt - 1);
+			for (long xa = val; xa > 9 && pad > 0; xa /= 10) {
+				pad--;
+			}
+			for (int xa = 0; xa < pad; xa++) {
+				tgt.append('0');
+			}
+		}
+		tgt.append(val);
+	}
+
+	/**
+	 * Formats a number of milliseconds for display (e.g.
+	 * in a log file), tailoring the output to how big
+	 * the value actually is.
+	 * <p>
+	 * Example outputs:
+	 * </p>
+	 * <ul>
+	 * <li>133ms</li>
+	 * <li>00:00:10.223</li>
+	 * <li>1.7 days</li>
+	 * <li>64 days</li>
+	 * </ul>
+	 */
+	public static String formatMillis(long theMillis) {
+		return formatMillis((double) theMillis);
+	}
+
+	/**
+	 * Formats a number of milliseconds for display (e.g.
+	 * in a log file), tailoring the output to how big
+	 * the value actually is.
+	 * <p>
+	 * Example outputs:
+	 * </p>
+	 * <ul>
+	 * <li>133ms</li>
+	 * <li>00:00:10.223</li>
+	 * <li>1.7 days</li>
+	 * <li>64 days</li>
+	 * </ul>
+	 */
+	public static String formatMillis(double theMillis) {
+		StringBuilder buf = new StringBuilder(20);
+		if (theMillis > 0.0 && theMillis < 1.0) {
+			buf.append(getSubMillisecondMillisFormat().format(theMillis));
+			buf.append("ms");
+		} else if (theMillis < (10 * DateUtils.MILLIS_PER_SECOND)) {
+			buf.append((int) theMillis);
+			buf.append("ms");
+		} else if (theMillis >= DateUtils.MILLIS_PER_DAY) {
+			double days = theMillis / DateUtils.MILLIS_PER_DAY;
+			if (days >= 10) {
+				buf.append(getTenDayFormat().format(days));
+				buf.append(" days");
+			} else if (days != 1.0f) {
+				buf.append(getDayFormat().format(days));
+				buf.append(" days");
+			} else {
+				buf.append(getDayFormat().format(days));
+				buf.append(" day");
+			}
+		} else {
+			long millisAsLong = (long) theMillis;
+			append(buf, "", 2, ((millisAsLong % DateUtils.MILLIS_PER_DAY) / DateUtils.MILLIS_PER_HOUR));
+			append(buf, ":", 2, ((millisAsLong % DateUtils.MILLIS_PER_HOUR) / DateUtils.MILLIS_PER_MINUTE));
+			append(buf, ":", 2, ((millisAsLong % DateUtils.MILLIS_PER_MINUTE) / DateUtils.MILLIS_PER_SECOND));
+			if (theMillis <= DateUtils.MILLIS_PER_MINUTE) {
+				append(buf, ".", 3, (millisAsLong % DateUtils.MILLIS_PER_SECOND));
+			}
+		}
+		return buf.toString();
+	}
+
+	private static long now() {
+		if (ourNowForUnitTest != null) {
+			return ourNowForUnitTest;
+		}
+		return System.currentTimeMillis();
+	}
+
+	@VisibleForTesting
+	static void setNowForUnitTestForUnitTest(Long theNowForUnitTest) {
+		ourNowForUnitTest = theNowForUnitTest;
+	}
+
 }

hapi-fhir-base/src/test/java/ca/uhn/fhir/util/LogUtilTest.java

@@ -0,0 +1,29 @@
+package ca.uhn.fhir.util;
+
+import org.junit.Test;
+import org.slf4j.Logger;
+import org.slf4j.event.Level;
+
+import static org.mockito.ArgumentMatchers.anyString;
+import static org.mockito.Mockito.*;
+
+public class LogUtilTest {
+
+	@Test
+	public void testLevels() {
+		Logger log = mock(Logger.class);
+		LogUtil.log(log, Level.TRACE, "HELLO");
+		LogUtil.log(log, Level.DEBUG, "HELLO");
+		LogUtil.log(log, Level.INFO, "HELLO");
+		LogUtil.log(log, Level.WARN, "HELLO");
+		LogUtil.log(log, Level.ERROR, "HELLO");
+
+		verify(log, times(1)).trace(anyString(),any(Object[].class));
+		verify(log, times(1)).debug(anyString(),any(Object[].class));
+		verify(log, times(1)).info(anyString(),any(Object[].class));
+		verify(log, times(1)).warn(anyString(),any(Object[].class));
+		verify(log, times(1)).error(anyString(),any(Object[].class));
+		verifyNoMoreInteractions(log);
+	}
+
+}

hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java

@@ -99,6 +99,7 @@ public class StopWatchTest {
 
 	@Test
 	public void testFormatMillis() {
+		assertEquals("0.134ms", StopWatch.formatMillis(0.1339d));
 		assertEquals("1000ms", StopWatch.formatMillis(DateUtils.MILLIS_PER_SECOND));
 		assertEquals("00:01:00.000", StopWatch.formatMillis(DateUtils.MILLIS_PER_MINUTE));
 		assertEquals("00:01:01", StopWatch.formatMillis(DateUtils.MILLIS_PER_MINUTE + DateUtils.MILLIS_PER_SECOND));

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirDao.java

@@ -10,6 +10,7 @@ import ca.uhn.fhir.jpa.model.entity.*;
 import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
 import ca.uhn.fhir.jpa.model.interceptor.api.IInterceptorBroadcaster;
 import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.search.ISearchCoordinatorSvc;
 import ca.uhn.fhir.jpa.search.PersistedJpaBundleProvider;
 import ca.uhn.fhir.jpa.searchparam.ResourceMetaParams;

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java

@@ -28,6 +28,7 @@ import ca.uhn.fhir.jpa.dao.r4.MatchResourceUrlService;
 import ca.uhn.fhir.jpa.model.entity.*;
 import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
 import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
+import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
 import ca.uhn.fhir.jpa.search.DatabaseBackedPagingProvider;
 import ca.uhn.fhir.jpa.search.PersistedJpaBundleProvider;
 import ca.uhn.fhir.jpa.search.reindex.IResourceReindexingSvc;
@@ -1132,7 +1133,9 @@ public abstract class BaseHapiFhirResourceDao<T extends IBaseResource> extends B
 		HashSet<Long> retVal = new HashSet<Long>();
 
 		String uuid = UUID.randomUUID().toString();
-		Iterator<Long> iter = builder.createQuery(theParams, uuid);
+		SearchRuntimeDetails searchRuntimeDetails = new SearchRuntimeDetails(uuid);
+
+		Iterator<Long> iter = builder.createQuery(theParams, searchRuntimeDetails);
 		while (iter.hasNext()) {
 			retVal.add(iter.next());
 		}

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/ISearchBuilder.java

@@ -21,6 +21,7 @@ package ca.uhn.fhir.jpa.dao;
  */
 
 import ca.uhn.fhir.context.FhirContext;
+import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
 import ca.uhn.fhir.jpa.searchparam.SearchParameterMap;
 import ca.uhn.fhir.model.api.Include;
 import ca.uhn.fhir.rest.param.DateRangeParam;
@@ -34,7 +35,7 @@ import java.util.Set;
 
 public interface ISearchBuilder {
 
-	IResultIterator createQuery(SearchParameterMap theParams, String theSearchUuid);
+	IResultIterator createQuery(SearchParameterMap theParams, SearchRuntimeDetails theSearchRuntime);
 
 	void setMaxResultsToFetch(Integer theMaxResultsToFetch);
 

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java

@@ -32,6 +32,7 @@ import ca.uhn.fhir.jpa.model.entity.*;
 import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
 import ca.uhn.fhir.jpa.model.interceptor.api.IInterceptorBroadcaster;
 import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
+import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
 import ca.uhn.fhir.jpa.model.util.StringNormalizer;
 import ca.uhn.fhir.jpa.searchparam.JpaRuntimeSearchParam;
 import ca.uhn.fhir.jpa.searchparam.MatchUrlService;
@@ -117,6 +118,8 @@ public class SearchBuilder implements ISearchBuilder {
 	private final boolean myDontUseHashesForSearch;
 	private final DaoConfig myDaoConfig;
 	@Autowired
+	protected IInterceptorBroadcaster myInterceptorBroadcaster;
+	@Autowired
 	protected IResourceTagDao myResourceTagDao;
 	@PersistenceContext(type = PersistenceContextType.TRANSACTION)
 	protected EntityManager myEntityManager;
@@ -140,8 +143,6 @@ public class SearchBuilder implements ISearchBuilder {
 	private MatchUrlService myMatchUrlService;
 	@Autowired
 	private IResourceIndexedCompositeStringUniqueDao myResourceIndexedCompositeStringUniqueDao;
-	@Autowired
-	private IInterceptorBroadcaster myInterceptorBroadcaster;
 	private List<Long> myAlsoIncludePids;
 	private CriteriaBuilder myBuilder;
 	private BaseHapiFhirDao<?> myCallingDao;
@@ -1549,10 +1550,10 @@ public class SearchBuilder implements ISearchBuilder {
 	}
 
 	@Override
-	public IResultIterator createQuery(SearchParameterMap theParams, String theSearchUuid) {
+	public IResultIterator createQuery(SearchParameterMap theParams, SearchRuntimeDetails theSearchRuntimeDetails) {
 		myParams = theParams;
 		myBuilder = myEntityManager.getCriteriaBuilder();
-		mySearchUuid = theSearchUuid;
+		mySearchUuid = theSearchRuntimeDetails.getSearchUuid();
 
 		if (ourTrackHandlersForUnitTest) {
 			ourLastHandlerParamsForUnitTest = theParams;
@@ -1564,7 +1565,7 @@ public class SearchBuilder implements ISearchBuilder {
 			myPidSet = new HashSet<>();
 		}
 
-		return new QueryIterator();
+		return new QueryIterator(theSearchRuntimeDetails);
 	}
 
 	private TypedQuery<Long> createQuery(SortSpec sort, Integer theMaximumResults, boolean theCount) {
@@ -2483,6 +2484,7 @@ public class SearchBuilder implements ISearchBuilder {
 
 	private final class QueryIterator extends BaseIterator<Long> implements IResultIterator {
 
+		private final SearchRuntimeDetails mySearchRuntimeDetails;
 		private boolean myFirst = true;
 		private IncludesIterator myIncludesIterator;
 		private Long myNext;
@@ -2490,10 +2492,10 @@ public class SearchBuilder implements ISearchBuilder {
 		private Iterator<Long> myResultsIterator;
 		private SortSpec mySort;
 		private boolean myStillNeedToFetchIncludes;
-		private StopWatch myStopwatch = null;
 		private int mySkipCount = 0;
 
-		private QueryIterator() {
+		private QueryIterator(SearchRuntimeDetails theSearchRuntimeDetails) {
+			mySearchRuntimeDetails = theSearchRuntimeDetails;
 			mySort = myParams.getSort();
 
 			// Includes are processed inline for $everything query
@@ -2504,10 +2506,6 @@ public class SearchBuilder implements ISearchBuilder {
 
 		private void fetchNext() {
 
-			if (myFirst) {
-				myStopwatch = new StopWatch();
-			}
-
 			// If we don't have a query yet, create one
 			if (myResultsIterator == null) {
 				if (myMaxResultsToFetch == null) {
@@ -2516,6 +2514,8 @@ public class SearchBuilder implements ISearchBuilder {
 
 				final TypedQuery<Long> query = createQuery(mySort, myMaxResultsToFetch, false);
 
+				mySearchRuntimeDetails.setQueryStopwatch(new StopWatch());
+
 				Query<Long> hibernateQuery = (Query<Long>) query;
 				hibernateQuery.setFetchSize(myFetchSize);
 				ScrollableResults scroll = hibernateQuery.scroll(ScrollMode.FORWARD_ONLY);
@@ -2543,7 +2543,7 @@ public class SearchBuilder implements ISearchBuilder {
 				if (myNext == null) {
 					while (myResultsIterator.hasNext()) {
 						Long next = myResultsIterator.next();
-						if (next != null)
+						if (next != null) {
 							if (myPidSet.add(next)) {
 								myNext = next;
 								break;
@@ -2552,6 +2552,7 @@ public class SearchBuilder implements ISearchBuilder {
 							}
 						}
 					}
+				}
 
 				if (myNext == null) {
 					if (myStillNeedToFetchIncludes) {
@@ -2577,13 +2578,15 @@ public class SearchBuilder implements ISearchBuilder {
 
 			} // if we need to fetch the next result
 
+			mySearchRuntimeDetails.setFoundMatchesCount(myPidSet.size());
+
 			if (myFirst) {
-				ourLog.debug("Initial query result returned in {}ms for query {}", myStopwatch.getMillis(), mySearchUuid);
+				myInterceptorBroadcaster.callHooks(Pointcut.PERFTRACE_SEARCH_FIRST_RESULT_LOADED, mySearchRuntimeDetails);
 				myFirst = false;
 			}
 
 			if (NO_MORE.equals(myNext)) {
-				ourLog.debug("Query found {} matches in {}ms for query {}", myPidSet.size(), myStopwatch.getMillis(), mySearchUuid);
+				myInterceptorBroadcaster.callHooks(Pointcut.PERFTRACE_SEARCH_SELECT_COMPLETE, mySearchRuntimeDetails);
 			}
 
 		}

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/index/IdHelperService.java

@@ -23,7 +23,9 @@ package ca.uhn.fhir.jpa.dao.index;
 import ca.uhn.fhir.jpa.dao.DaoConfig;
 import ca.uhn.fhir.jpa.dao.data.IForcedIdDao;
 import ca.uhn.fhir.jpa.model.entity.ForcedId;
-import ca.uhn.fhir.model.dstu2.resource.Specimen;
+import ca.uhn.fhir.jpa.model.interceptor.api.IInterceptorBroadcaster;
+import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
+import ca.uhn.fhir.jpa.model.search.PerformanceMessage;
 import ca.uhn.fhir.model.primitive.IdDt;
 import ca.uhn.fhir.rest.server.exceptions.ResourceNotFoundException;
 import com.google.common.collect.ListMultimap;
@@ -43,6 +45,8 @@ public class IdHelperService {
 	protected IForcedIdDao myForcedIdDao;
 	@Autowired(required = true)
 	private DaoConfig myDaoConfig;
+	@Autowired
+	private IInterceptorBroadcaster myInterceptorBroadcaster;
 
 	public void delete(ForcedId forcedId) {
 		myForcedIdDao.delete(forcedId);
@@ -51,7 +55,7 @@ public class IdHelperService {
 	public Long translateForcedIdToPid(String theResourceName, String theResourceId) throws ResourceNotFoundException {
 		// We only pass 1 input in so only 0..1 will come back
 		IdDt id = new IdDt(theResourceName, theResourceId);
-		List<Long> matches = translateForcedIdToPids(myDaoConfig, myForcedIdDao, Collections.singletonList(id));
+		List<Long> matches = translateForcedIdToPids(myDaoConfig, myInterceptorBroadcaster, myForcedIdDao, Collections.singletonList(id));
 		assert matches.size() <= 1;
 		if (matches.isEmpty()) {
 			throw new ResourceNotFoundException(id);
@@ -60,10 +64,10 @@ public class IdHelperService {
 	}
 
 	public List<Long> translateForcedIdToPids(Collection<IIdType> theId) {
-		return IdHelperService.translateForcedIdToPids(myDaoConfig, myForcedIdDao, theId);
+		return IdHelperService.translateForcedIdToPids(myDaoConfig, myInterceptorBroadcaster, myForcedIdDao, theId);
 	}
 
-	static List<Long> translateForcedIdToPids(DaoConfig theDaoConfig, IForcedIdDao theForcedIdDao, Collection<IIdType> theId) {
+	static List<Long> translateForcedIdToPids(DaoConfig theDaoConfig, IInterceptorBroadcaster theInterceptorBroadcaster, IForcedIdDao theForcedIdDao, Collection<IIdType> theId) {
 		theId.forEach(id -> Validate.isTrue(id.hasIdPart()));
 
 		if (theId.isEmpty()) {
@@ -89,7 +93,13 @@ public class IdHelperService {
 			String nextResourceType = nextEntry.getKey();
 			Collection<String> nextIds = nextEntry.getValue();
 			if (isBlank(nextResourceType)) {
+
+				PerformanceMessage msg = new PerformanceMessage()
+					.setMessage("This search uses unqualified resource IDs (an ID without a resource type). This is less efficient than using a qualified type.");
+				theInterceptorBroadcaster.callHooks(Pointcut.PERFTRACE_MESSAGE, msg);
+
 				retVal.addAll(theForcedIdDao.findByForcedId(nextIds));
+
 			} else {
 				retVal.addAll(theForcedIdDao.findByTypeAndForcedId(nextResourceType, nextIds));
 			}

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/entity/Search.java

@@ -1,5 +1,6 @@
 package ca.uhn.fhir.jpa.entity;
 
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.searchparam.SearchParameterMap;
 import ca.uhn.fhir.model.api.Include;
 import ca.uhn.fhir.rest.param.DateRangeParam;

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/interceptor/PerformanceTracingLoggingInterceptor.java

@@ -0,0 +1,62 @@
+package ca.uhn.fhir.jpa.interceptor;
+
+import ca.uhn.fhir.jpa.model.interceptor.api.Hook;
+import ca.uhn.fhir.jpa.model.interceptor.api.Interceptor;
+import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
+import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
+import ca.uhn.fhir.util.LogUtil;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.slf4j.event.Level;
+
+@Interceptor(manualRegistration = true)
+public class PerformanceTracingLoggingInterceptor {
+	private static final Logger ourLog = LoggerFactory.getLogger(PerformanceTracingLoggingInterceptor.class);
+	private final Logger myLog;
+	private final Level myLevel;
+
+	/**
+	 * Constructor that logs to this class with a level of INFO
+	 */
+	public PerformanceTracingLoggingInterceptor() {
+		this(ourLog, Level.INFO);
+	}
+
+	/**
+	 * Constructor that logs to a custom logger and level
+	 */
+	public PerformanceTracingLoggingInterceptor(Logger theLog, Level theLevel) {
+		myLog = theLog;
+		myLevel = theLevel;
+	}
+
+	@Hook(value = Pointcut.PERFTRACE_SEARCH_FIRST_RESULT_LOADED)
+	public void searchFirstResultLoaded(SearchRuntimeDetails theOutcome) {
+		log("Initial query result returned in {} for query {}", theOutcome.getQueryStopwatch(), theOutcome.getSearchUuid());
+	}
+
+	@Hook(value = Pointcut.PERFTRACE_SEARCH_SELECT_COMPLETE)
+	public void searchSelectComplete(SearchRuntimeDetails theOutcome) {
+		log("Query found {} matches in {} for query {}", theOutcome.getFoundMatchesCount(), theOutcome.getQueryStopwatch(), theOutcome.getSearchUuid());
+	}
+
+	@Hook(value = Pointcut.PERFTRACE_SEARCH_COMPLETE)
+	public void searchComplete(SearchRuntimeDetails theOutcome) {
+		log("Query {} is complete in {} - Found {} matches", theOutcome.getSearchUuid(), theOutcome.getQueryStopwatch(), theOutcome.getFoundMatchesCount());
+	}
+
+	@Hook(value = Pointcut.PERFTRACE_SEARCH_PASS_COMPLETE)
+	public void searchPassComplete(SearchRuntimeDetails theOutcome) {
+		log("Query {} pass complete and set to status {} in {} - Found {} matches", theOutcome.getSearchUuid(), theOutcome.getSearchStatus(), theOutcome.getQueryStopwatch(), theOutcome.getFoundMatchesCount());
+	}
+
+	@Hook(value = Pointcut.PERFTRACE_SEARCH_FAILED)
+	public void searchFailed(SearchRuntimeDetails theOutcome) {
+		log("Query {} failed in {} - Found {} matches", theOutcome.getSearchUuid(), theOutcome.getQueryStopwatch(), theOutcome.getFoundMatchesCount());
+	}
+
+	private void log(String theMessage, Object... theArgs) {
+		LogUtil.log(myLog, myLevel, theMessage, theArgs);
+	}
+
+}

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/PersistedJpaSearchFirstPageBundleProvider.java

@@ -26,16 +26,13 @@ import org.hl7.fhir.instance.model.api.IBaseResource;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.springframework.transaction.PlatformTransactionManager;
-import org.springframework.transaction.TransactionStatus;
-import org.springframework.transaction.support.TransactionCallback;
 import org.springframework.transaction.support.TransactionTemplate;
 
 import ca.uhn.fhir.jpa.dao.IDao;
 import ca.uhn.fhir.jpa.dao.ISearchBuilder;
 import ca.uhn.fhir.jpa.entity.Search;
-import ca.uhn.fhir.jpa.entity.SearchStatusEnum;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl.SearchTask;
-import ca.uhn.fhir.rest.server.exceptions.InternalErrorException;
 
 public class PersistedJpaSearchFirstPageBundleProvider extends PersistedJpaBundleProvider {
 	private static final Logger ourLog = LoggerFactory.getLogger(PersistedJpaSearchFirstPageBundleProvider.class);

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java

@@ -26,6 +26,10 @@ import ca.uhn.fhir.jpa.dao.data.ISearchDao;
 import ca.uhn.fhir.jpa.dao.data.ISearchIncludeDao;
 import ca.uhn.fhir.jpa.dao.data.ISearchResultDao;
 import ca.uhn.fhir.jpa.entity.*;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
+import ca.uhn.fhir.jpa.model.interceptor.api.IInterceptorBroadcaster;
+import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
+import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
 import ca.uhn.fhir.jpa.searchparam.SearchParameterMap;
 import ca.uhn.fhir.model.api.Include;
 import ca.uhn.fhir.rest.api.CacheControlDirective;
@@ -69,6 +73,7 @@ import javax.annotation.Nullable;
 import javax.annotation.PostConstruct;
 import javax.persistence.EntityManager;
 import java.util.*;
+import java.util.List;
 import java.util.concurrent.*;
 
 import static org.apache.commons.lang3.ObjectUtils.defaultIfNull;
@@ -96,6 +101,8 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 	@Autowired
 	private ISearchResultDao mySearchResultDao;
 	@Autowired
+	private IInterceptorBroadcaster myInterceptorBroadcaster;
+	@Autowired
 	private PlatformTransactionManager myManagedTxManager;
 	@Autowired
 	private DaoRegistry myDaoRegistry;
@@ -290,6 +297,8 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 		if (theParams.isLoadSynchronous() || loadSynchronousUpTo != null) {
 
 			ourLog.debug("Search {} is loading in synchronous mode", searchUuid);
+			SearchRuntimeDetails searchRuntimeDetails = new SearchRuntimeDetails(searchUuid);
+			searchRuntimeDetails.setLoadSynchronous(true);
 
 			// Execute the query and make sure we return distinct results
 			TransactionTemplate txTemplate = new TransactionTemplate(myManagedTxManager);
@@ -299,7 +308,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 				// Load the results synchronously
 				final List<Long> pids = new ArrayList<>();
 
-				Iterator<Long> resultIter = sb.createQuery(theParams, searchUuid);
+				Iterator<Long> resultIter = sb.createQuery(theParams, searchRuntimeDetails);
 				while (resultIter.hasNext()) {
 					pids.add(resultIter.next());
 					if (loadSynchronousUpTo != null && pids.size() >= loadSynchronousUpTo) {
@@ -449,10 +458,15 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 	}
 
 	@VisibleForTesting
-	public void setDaoRegistryForUnitTest(DaoRegistry theDaoRegistry) {
+	void setDaoRegistryForUnitTest(DaoRegistry theDaoRegistry) {
 		myDaoRegistry = theDaoRegistry;
 	}
 
+	@VisibleForTesting
+	void setInterceptorBroadcasterForUnitTest(IInterceptorBroadcaster theInterceptorBroadcaster) {
+		myInterceptorBroadcaster = theInterceptorBroadcaster;
+	}
+
 	public abstract class BaseTask implements Callable<Void> {
 		private final SearchParameterMap myParams;
 		private final IDao myCallingDao;
@@ -468,6 +482,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 		private boolean myAdditionalPrefetchThresholdsRemaining;
 		private List<Long> myPreviouslyAddedResourcePids;
 		private Integer myMaxResultsToFetch;
+		private SearchRuntimeDetails mySearchRuntimeDetails;
 
 		/**
 		 * Constructor
@@ -478,6 +493,12 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 			myParams = theParams;
 			myResourceType = theResourceType;
 			myCompletionLatch = new CountDownLatch(1);
+			mySearchRuntimeDetails = new SearchRuntimeDetails(mySearch.getUuid());
+			mySearchRuntimeDetails.setQueryString(theParams.toNormalizedQueryString(theCallingDao.getContext()));
+		}
+
+		public SearchRuntimeDetails getSearchRuntimeDetails() {
+			return mySearchRuntimeDetails;
 		}
 
 		protected Search getSearch() {
@@ -694,6 +715,13 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 					}
 				});
 
+				mySearchRuntimeDetails.setSearchStatus(mySearch.getStatus());
+				if (mySearch.getStatus() == SearchStatusEnum.FINISHED) {
+					myInterceptorBroadcaster.callHooks(Pointcut.PERFTRACE_SEARCH_COMPLETE, mySearchRuntimeDetails);
+				} else {
+					myInterceptorBroadcaster.callHooks(Pointcut.PERFTRACE_SEARCH_PASS_COMPLETE, mySearchRuntimeDetails);
+				}
+
 				ourLog.info("Have completed search for [{}{}] and found {} resources in {}ms - Status is {}", mySearch.getResourceType(), mySearch.getSearchQueryString(), mySyncedPids.size(), sw.getMillis(), mySearch.getStatus());
 
 			} catch (Throwable t) {
@@ -731,6 +759,9 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 				mySearch.setFailureCode(failureCode);
 				mySearch.setStatus(SearchStatusEnum.FAILED);
 
+				mySearchRuntimeDetails.setSearchStatus(mySearch.getStatus());
+				myInterceptorBroadcaster.callHooks(Pointcut.PERFTRACE_SEARCH_FAILED, mySearchRuntimeDetails);
+
 				saveSearch();
 
 			} finally {
@@ -860,7 +891,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
 			/*
 			 * Construct the SQL query we'll be sending to the database
 			 */
-			IResultIterator resultIterator = sb.createQuery(myParams, mySearch.getUuid());
+			IResultIterator resultIterator = sb.createQuery(myParams, mySearchRuntimeDetails);
 			assert (resultIterator != null);
 
 			/*

hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/SubscriptionInterceptorLoader.java

@@ -57,12 +57,12 @@ public class SubscriptionInterceptorLoader {
 		if (!supportedSubscriptionTypes.isEmpty()) {
 			loadSubscriptions();
 			ourLog.info("Registering subscription activating interceptor");
-			myInterceptorRegistry.registerInterceptor(mySubscriptionActivatingInterceptor);
+			myInterceptorRegistry.registerAnonymousInterceptor(mySubscriptionActivatingInterceptor);
 		}
 		if (myDaoConfig.isSubscriptionMatchingEnabled()) {
 			mySubscriptionMatcherInterceptor.start();
 			ourLog.info("Registering subscription matcher interceptor");
-			myInterceptorRegistry.registerInterceptor(mySubscriptionMatcherInterceptor);
+			myInterceptorRegistry.registerAnonymousInterceptor(mySubscriptionMatcherInterceptor);
 		}
 	}
 

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/BaseJpaTest.java

@@ -142,7 +142,7 @@ public abstract class BaseJpaTest {
 
 	protected CountDownLatch registerLatchHookInterceptor(int theCount, Pointcut theLatchPointcut) {
 		CountDownLatch deliveryLatch = new CountDownLatch(theCount);
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(theLatchPointcut, Integer.MAX_VALUE, t -> deliveryLatch.countDown());
+		myInterceptorRegistry.registerAnonymousInterceptor(theLatchPointcut, Integer.MAX_VALUE, (thePointcut, t) -> deliveryLatch.countDown());
 		return deliveryLatch;
 	}
 

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/BaseJpaR4Test.java

@@ -5,6 +5,7 @@ import ca.uhn.fhir.jpa.config.TestR4Config;
 import ca.uhn.fhir.jpa.dao.*;
 import ca.uhn.fhir.jpa.dao.data.*;
 import ca.uhn.fhir.jpa.dao.dstu2.FhirResourceDaoDstu2SearchNoFtTest;
+import ca.uhn.fhir.jpa.interceptor.PerformanceTracingLoggingInterceptor;
 import ca.uhn.fhir.jpa.model.entity.ModelConfig;
 import ca.uhn.fhir.jpa.model.entity.ResourceIndexedSearchParamString;
 import ca.uhn.fhir.jpa.model.entity.ResourceTable;
@@ -286,6 +287,8 @@ public abstract class BaseJpaR4Test extends BaseJpaTest {
 	@Autowired
 	protected SubscriptionRegistry mySubscriptionRegistry;
 
+	private PerformanceTracingLoggingInterceptor myPerformanceTracingLoggingInterceptor;
+
 	@After()
 	public void afterCleanupDao() {
 		myDaoConfig.setExpireSearchResults(new DaoConfig().isExpireSearchResults());
@@ -318,6 +321,9 @@ public abstract class BaseJpaR4Test extends BaseJpaTest {
 	public void beforeCreateInterceptor() {
 		myInterceptor = mock(IServerInterceptor.class);
 		myDaoConfig.setInterceptors(myInterceptor);
+
+		myPerformanceTracingLoggingInterceptor = new PerformanceTracingLoggingInterceptor();
+		myInterceptorRegistry.registerAnonymousInterceptor(myPerformanceTracingLoggingInterceptor);
 	}
 
 	@Before
@@ -345,6 +351,8 @@ public abstract class BaseJpaR4Test extends BaseJpaTest {
 		myDaoConfig.setHardTagListLimit(1000);
 		myDaoConfig.setIncludeLimit(2000);
 		myFhirCtx.setParserErrorHandler(new StrictErrorHandler());
+
+		myInterceptorRegistry.unregisterInterceptor(myPerformanceTracingLoggingInterceptor);
 	}
 
 	@Override

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4SearchNoFtTest.java

@@ -1,7 +1,6 @@
 package ca.uhn.fhir.jpa.dao.r4;
 
 import ca.uhn.fhir.context.RuntimeResourceDefinition;
-import ca.uhn.fhir.jpa.util.CircularQueueCaptureQueriesListener;
 import ca.uhn.fhir.jpa.dao.DaoConfig;
 import ca.uhn.fhir.jpa.model.entity.*;
 import ca.uhn.fhir.jpa.searchparam.MatchUrlService;
@@ -19,7 +18,6 @@ import ca.uhn.fhir.rest.server.exceptions.MethodNotAllowedException;
 import com.google.common.collect.Lists;
 import org.apache.commons.io.IOUtils;
 import org.apache.commons.lang3.StringUtils;
-import org.apache.http.NameValuePair;
 import org.hl7.fhir.instance.model.api.IAnyResource;
 import org.hl7.fhir.instance.model.api.IBaseResource;
 import org.hl7.fhir.instance.model.api.IIdType;
@@ -163,7 +161,7 @@ public class FhirResourceDaoR4SearchNoFtTest extends BaseJpaR4Test {
 		conditionA.getAsserter().setReference(patientId);
 		myConditionDao.create(conditionA);
 
-		String criteria = "_has:Condition:subject:code=http://snomed.info/sct|55822003,http://snomed.info/sct|55822004&"+
+		String criteria = "_has:Condition:subject:code=http://snomed.info/sct|55822003,http://snomed.info/sct|55822004&" +
 			"_has:Condition:asserter:code=http://snomed.info/sct|55822003,http://snomed.info/sct|55822005";
 		SearchParameterMap map = myMatchUrlService.translateMatchUrl(criteria, myFhirCtx.getResourceDefinition(Patient.class));
 
@@ -190,7 +188,7 @@ public class FhirResourceDaoR4SearchNoFtTest extends BaseJpaR4Test {
 		conditionA.getAsserter().setReference(patientId);
 		myConditionDao.create(conditionA);
 
-		String criteria = "_has:Condition:subject:code=http://snomed.info/sct|55822003,http://snomed.info/sct|55822005&"+
+		String criteria = "_has:Condition:subject:code=http://snomed.info/sct|55822003,http://snomed.info/sct|55822005&" +
 			"_has:Condition:asserter:code=http://snomed.info/sct|55822003,http://snomed.info/sct|55822004";
 		SearchParameterMap map = myMatchUrlService.translateMatchUrl(criteria, myFhirCtx.getResourceDefinition(Patient.class));
 
@@ -1346,7 +1344,9 @@ public class FhirResourceDaoR4SearchNoFtTest extends BaseJpaR4Test {
 			IBundleProvider found = myPatientDao.search(map);
 			Set<String> dates = new HashSet<>();
 			for (int i = 0; i < 9; i++) {
-				Patient nextResource = (Patient) found.getResources(i, i + 1).get(0);
+				List<IBaseResource> resources = found.getResources(i, i + 1);
+				assertThat("Failed to load range " + i + " - " + (i + 1), resources, hasSize(1));
+				Patient nextResource = (Patient) resources.get(0);
 				dates.add(nextResource.getBirthDateElement().getValueAsString());
 			}
 
@@ -2177,7 +2177,7 @@ public class FhirResourceDaoR4SearchNoFtTest extends BaseJpaR4Test {
 		myCaptureQueriesListener.clear();
 		result = toList(myObservationDao.search(new SearchParameterMap().setLoadSynchronous(true).add(Observation.SP_SUBJECT, new ReferenceParam("testSearchResourceLinkWithTextLogicalId99"))));
 		myCaptureQueriesListener.logSelectQueriesForCurrentThread();
-		assertEquals(result.toString(),0, result.size());
+		assertEquals(result.toString(), 0, result.size());
 
 		// And with a numeric ID that doesn't exist
 		result = toList(myObservationDao.search(new SearchParameterMap().setLoadSynchronous(true).add(Observation.SP_SUBJECT, new ReferenceParam("999999999999999"))));
@@ -2570,7 +2570,6 @@ public class FhirResourceDaoR4SearchNoFtTest extends BaseJpaR4Test {
 	}
 
 
-
 	@Test
 	public void testSearchTokenParam() {
 		Patient patient = new Patient();
@@ -2704,7 +2703,7 @@ public class FhirResourceDaoR4SearchNoFtTest extends BaseJpaR4Test {
 			map.setLoadSynchronous(true);
 			map.add(Patient.SP_FAMILY, new StringAndListParam()
 				.addAnd(new StringParam("STRINGA"))
-				.addAnd(new StringParam( "STRINGB"))
+				.addAnd(new StringParam("STRINGB"))
 			);
 			myCaptureQueriesListener.clear();
 			IBundleProvider retrieved = myPatientDao.search(map);

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4SearchOptimizedTest.java

@@ -2,7 +2,7 @@ package ca.uhn.fhir.jpa.dao.r4;
 
 import ca.uhn.fhir.jpa.dao.DaoConfig;
 import ca.uhn.fhir.jpa.entity.Search;
-import ca.uhn.fhir.jpa.entity.SearchStatusEnum;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.model.entity.ResourceTable;
 import ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl;
 import ca.uhn.fhir.jpa.searchparam.SearchParameterMap;

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4SearchPageExpiryTest.java

@@ -4,7 +4,7 @@ import ca.uhn.fhir.jpa.dao.DaoConfig;
 import ca.uhn.fhir.jpa.searchparam.SearchParameterMap;
 import ca.uhn.fhir.jpa.dao.data.ISearchDao;
 import ca.uhn.fhir.jpa.entity.Search;
-import ca.uhn.fhir.jpa.entity.SearchStatusEnum;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.search.StaleSearchDeletingSvcImpl;
 import ca.uhn.fhir.jpa.util.TestUtil;
 import ca.uhn.fhir.util.StopWatch;

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4Test.java

@@ -5,7 +5,7 @@ import ca.uhn.fhir.jpa.dao.BaseHapiFhirResourceDao;
 import ca.uhn.fhir.jpa.dao.DaoConfig;
 import ca.uhn.fhir.jpa.dao.IFhirResourceDao;
 import ca.uhn.fhir.jpa.entity.Search;
-import ca.uhn.fhir.jpa.entity.SearchStatusEnum;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.model.entity.*;
 import ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl;
 import ca.uhn.fhir.jpa.searchparam.SearchParamConstants;

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4UniqueSearchParamTest.java

@@ -460,6 +460,7 @@ public class FhirResourceDaoR4UniqueSearchParamTest extends BaseJpaR4Test {
 			.setValue(new BooleanType(true));
 		mySearchParameterDao.create(sp);
 		mySearchParamRegistry.forceRefresh();
+		ourLog.info(myFhirCtx.newJsonParser().setPrettyPrint(true).encodeResourceToString(sp));
 
 		// Now create matching/non-matching resources
 		Patient pt = new Patient();

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/CompositionDocumentR4Test.java

@@ -2,7 +2,7 @@ package ca.uhn.fhir.jpa.provider.r4;
 
 import ca.uhn.fhir.jpa.dao.DaoConfig;
 import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
-import ca.uhn.fhir.jpa.model.interceptor.api.IAnonymousLambdaHook;
+import ca.uhn.fhir.jpa.model.interceptor.api.IAnonymousInterceptor;
 import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
 import ca.uhn.fhir.parser.StrictErrorHandler;
 import ca.uhn.fhir.rest.api.EncodingEnum;
@@ -32,6 +32,7 @@ import static org.hamcrest.Matchers.hasItem;
 import static org.hamcrest.Matchers.hasItems;
 import static org.junit.Assert.assertNull;
 import static org.junit.Assert.assertThat;
+import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.times;
 
@@ -137,13 +138,13 @@ public class CompositionDocumentR4Test extends BaseResourceProviderR4Test {
 	@Test
 	public void testInterceptorHookIsCalledForAllContents_RESOURCE_MAY_BE_RETURNED() throws IOException {
 
-		IAnonymousLambdaHook pointcut = mock(IAnonymousLambdaHook.class);
+		IAnonymousInterceptor pointcut = mock(IAnonymousInterceptor.class);
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.RESOURCE_MAY_BE_RETURNED, pointcut);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.RESOURCE_MAY_BE_RETURNED, pointcut);
 
 		String theUrl = ourServerBase + "/" + compId + "/$document?_format=json";
 		fetchBundle(theUrl, EncodingEnum.JSON);
 
-		Mockito.verify(pointcut, times(10)).invoke(myHookParamsCaptor.capture());
+		Mockito.verify(pointcut, times(10)).invoke(eq(Pointcut.RESOURCE_MAY_BE_RETURNED), myHookParamsCaptor.capture());
 
 		List<String> returnedClasses = myHookParamsCaptor
 			.getAllValues()

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/HookInterceptorR4Test.java

@@ -17,7 +17,7 @@ public class HookInterceptorR4Test extends BaseResourceProviderR4Test {
 
 	@Test
 	public void testOP_PRESTORAGE_RESOURCE_CREATED_ModifyResource() {
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.OP_PRESTORAGE_RESOURCE_CREATED, t->{
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.OP_PRESTORAGE_RESOURCE_CREATED, (thePointcut, t)->{
 			Patient contents = (Patient) t.get(IBaseResource.class, 0);
 			contents.getNameFirstRep().setFamily("NEWFAMILY");
 		});
@@ -36,7 +36,7 @@ public class HookInterceptorR4Test extends BaseResourceProviderR4Test {
 
 	@Test
 	public void testOP_PRECOMMIT_RESOURCE_CREATED_ModifyResource() {
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, t->{
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, (thePointcut, t)->{
 			Patient contents = (Patient) t.get(IBaseResource.class, 0);
 			contents.getNameFirstRep().setFamily("NEWFAMILY");
 		});
@@ -59,7 +59,7 @@ public class HookInterceptorR4Test extends BaseResourceProviderR4Test {
 		p.setActive(true);
 		IIdType id = ourClient.create().resource(p).execute().getId();
 
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.OP_PRESTORAGE_RESOURCE_UPDATED, t->{
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.OP_PRESTORAGE_RESOURCE_UPDATED, (thePointcut, t)->{
 			Patient contents = (Patient) t.get(IBaseResource.class, 1);
 			contents.getNameFirstRep().setFamily("NEWFAMILY");
 		});
@@ -83,7 +83,7 @@ public class HookInterceptorR4Test extends BaseResourceProviderR4Test {
 		p.setActive(true);
 		IIdType id = ourClient.create().resource(p).execute().getId();
 
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.OP_PRECOMMIT_RESOURCE_UPDATED, t->{
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.OP_PRECOMMIT_RESOURCE_UPDATED, (thePointcut, t)->{
 			Patient contents = (Patient) t.get(IBaseResource.class, 1);
 			contents.getNameFirstRep().setFamily("NEWFAMILY");
 		});

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/ResourceProviderInterceptorR4Test.java

@@ -1,5 +1,11 @@
 package ca.uhn.fhir.jpa.provider.r4;
 
+import ca.uhn.fhir.jpa.dao.DaoConfig;
+import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
+import ca.uhn.fhir.jpa.model.interceptor.api.IAnonymousInterceptor;
+import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
+import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.parser.IParser;
 import ca.uhn.fhir.rest.api.Constants;
 import ca.uhn.fhir.rest.api.RestOperationTypeEnum;
@@ -13,6 +19,7 @@ import ca.uhn.fhir.rest.server.interceptor.InterceptorAdapter;
 import ca.uhn.fhir.rest.server.interceptor.ServerOperationInterceptorAdapter;
 import ca.uhn.fhir.rest.server.servlet.ServletRequestDetails;
 import ca.uhn.fhir.util.TestUtil;
+import com.google.common.collect.Lists;
 import org.apache.commons.io.IOUtils;
 import org.apache.http.client.methods.CloseableHttpResponse;
 import org.apache.http.client.methods.HttpPost;
@@ -29,14 +36,19 @@ import org.junit.After;
 import org.junit.AfterClass;
 import org.junit.Test;
 import org.mockito.ArgumentCaptor;
+import org.mockito.Captor;
+import org.mockito.Mock;
 
 import javax.servlet.ServletException;
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 import java.io.IOException;
 import java.nio.charset.StandardCharsets;
+import java.util.ArrayList;
+import java.util.List;
 import java.util.stream.Collectors;
 
+import static org.hamcrest.Matchers.in;
 import static org.hamcrest.Matchers.startsWith;
 import static org.junit.Assert.*;
 import static org.mockito.ArgumentMatchers.any;
@@ -48,6 +60,7 @@ public class ResourceProviderInterceptorR4Test extends BaseResourceProviderR4Tes
 	private IServerOperationInterceptor myDaoInterceptor;
 
 	private IServerOperationInterceptor myServerInterceptor;
+	private List<Object> myInterceptors = new ArrayList<>();
 
 	@Override
 	@After
@@ -55,7 +68,11 @@ public class ResourceProviderInterceptorR4Test extends BaseResourceProviderR4Tes
 		super.after();
 
 		myDaoConfig.getInterceptors().remove(myDaoInterceptor);
+		myDaoConfig.setSearchPreFetchThresholds(new DaoConfig().getSearchPreFetchThresholds());
 		ourRestServer.unregisterInterceptor(myServerInterceptor);
+
+		myInterceptorRegistry.unregisterInterceptors(myInterceptors);
+		myInterceptors.clear();
 	}
 
 	@Override
@@ -90,6 +107,51 @@ public class ResourceProviderInterceptorR4Test extends BaseResourceProviderR4Tes
 		when(myServerInterceptor.outgoingResponse(any(RequestDetails.class), any(ResponseDetails.class), any(HttpServletRequest.class), any(HttpServletResponse.class))).thenReturn(true);
 	}
 
+	@Mock
+	private IAnonymousInterceptor myHook;
+
+	@Captor
+	private ArgumentCaptor<HookParams> myParamsCaptor;
+
+	@Test
+	public void testPerfInterceptors() {
+		myDaoConfig.setSearchPreFetchThresholds(Lists.newArrayList(15, 100));
+		for (int i = 0; i < 30; i++) {
+			Patient p = new Patient();
+			p.addName().setFamily("FAM"+i);
+			myPatientDao.create(p);
+		}
+
+		IAnonymousInterceptor interceptor = mock(IAnonymousInterceptor.class);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.PERFTRACE_SEARCH_FIRST_RESULT_LOADED, interceptor);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.PERFTRACE_SEARCH_COMPLETE, interceptor);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.PERFTRACE_SEARCH_FAILED, interceptor);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.PERFTRACE_SEARCH_PASS_COMPLETE, interceptor);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.PERFTRACE_SEARCH_SELECT_COMPLETE, interceptor);
+		myInterceptors.add(interceptor);
+
+		Bundle results = ourClient.search().forResource(Patient.class).returnBundle(Bundle.class).execute();
+		verify(interceptor, times(1)).invoke(eq(Pointcut.PERFTRACE_SEARCH_FIRST_RESULT_LOADED), myParamsCaptor.capture());
+		verify(interceptor, times(1)).invoke(eq(Pointcut.PERFTRACE_SEARCH_SELECT_COMPLETE), myParamsCaptor.capture());
+		verify(interceptor, times(0)).invoke(eq(Pointcut.PERFTRACE_SEARCH_COMPLETE), myParamsCaptor.capture());
+		verify(interceptor, times(1)).invoke(eq(Pointcut.PERFTRACE_SEARCH_PASS_COMPLETE), myParamsCaptor.capture());
+		verify(interceptor, times(0)).invoke(eq(Pointcut.PERFTRACE_SEARCH_FAILED), myParamsCaptor.capture());
+
+		SearchRuntimeDetails details = myParamsCaptor.getAllValues().get(0).get(SearchRuntimeDetails.class);
+		assertEquals(SearchStatusEnum.PASSCMPLET, details.getSearchStatus());
+
+		// Load the next (and final) page
+		reset(interceptor);
+		results = ourClient.loadPage().next(results).execute();
+		verify(interceptor, times(1)).invoke(eq(Pointcut.PERFTRACE_SEARCH_FIRST_RESULT_LOADED), myParamsCaptor.capture());
+		verify(interceptor, times(1)).invoke(eq(Pointcut.PERFTRACE_SEARCH_SELECT_COMPLETE), myParamsCaptor.capture());
+		verify(interceptor, times(1)).invoke(eq(Pointcut.PERFTRACE_SEARCH_COMPLETE), myParamsCaptor.capture());
+		verify(interceptor, times(0)).invoke(eq(Pointcut.PERFTRACE_SEARCH_PASS_COMPLETE), myParamsCaptor.capture());
+		verify(interceptor, times(0)).invoke(eq(Pointcut.PERFTRACE_SEARCH_FAILED), myParamsCaptor.capture());
+
+	}
+
+
 	@Test
 	public void testCreateConditionalNoOpResourceInTransaction() throws Exception {
 		String methodName = "foo";
@@ -154,15 +216,12 @@ public class ResourceProviderInterceptorR4Test extends BaseResourceProviderR4Tes
 
 		HttpPost post = new HttpPost(ourServerBase + "/Patient");
 		post.setEntity(new StringEntity(resource, ContentType.create(Constants.CT_FHIR_XML, "UTF-8")));
-		CloseableHttpResponse response = ourHttpClient.execute(post);
+		try (CloseableHttpResponse response = ourHttpClient.execute(post)) {
-		try {
 			String resp = IOUtils.toString(response.getEntity().getContent(), StandardCharsets.UTF_8);
 			ourLog.info("Response was: {}", resp);
 			assertEquals(201, response.getStatusLine().getStatusCode());
 			String newIdString = response.getFirstHeader(Constants.HEADER_LOCATION_LC).getValue();
 			assertThat(newIdString, startsWith(ourServerBase + "/Patient/"));
-		} finally {
-			response.close();
 		}
 
 		ArgumentCaptor<ActionRequestDetails> ardCaptor = ArgumentCaptor.forClass(ActionRequestDetails.class);
@@ -235,7 +294,7 @@ public class ResourceProviderInterceptorR4Test extends BaseResourceProviderR4Tes
 	}
 
 	@Test
-	public void testCreateReflexResourceTheHardWay() throws IOException, ServletException {
+	public void testCreateReflexResourceTheHardWay() {
 		ServerOperationInterceptorAdapter interceptor = new ReflexInterceptor();
 
 		ourRestServer.registerInterceptor(interceptor);
@@ -287,15 +346,12 @@ public class ResourceProviderInterceptorR4Test extends BaseResourceProviderR4Tes
 
 		HttpPost post = new HttpPost(ourServerBase + "/Patient");
 		post.setEntity(new StringEntity(resource, ContentType.create(Constants.CT_FHIR_XML, "UTF-8")));
-		CloseableHttpResponse response = ourHttpClient.execute(post);
+		try (CloseableHttpResponse response = ourHttpClient.execute(post)) {
-		try {
 			String resp = IOUtils.toString(response.getEntity().getContent(), StandardCharsets.UTF_8);
 			ourLog.info("Response was: {}", resp);
 			assertEquals(201, response.getStatusLine().getStatusCode());
 			String newIdString = response.getFirstHeader(Constants.HEADER_LOCATION_LC).getValue();
 			assertThat(newIdString, startsWith(ourServerBase + "/Patient/"));
-		} finally {
-			response.close();
 		}
 
 		ArgumentCaptor<ActionRequestDetails> ardCaptor = ArgumentCaptor.forClass(ActionRequestDetails.class);
@@ -371,11 +427,8 @@ public class ResourceProviderInterceptorR4Test extends BaseResourceProviderR4Tes
 		String resource = myFhirCtx.newXmlParser().encodeResourceToString(theBundle);
 		HttpPost post = new HttpPost(ourServerBase + "/");
 		post.setEntity(new StringEntity(resource, ContentType.create(Constants.CT_FHIR_XML, "UTF-8")));
-		CloseableHttpResponse response = ourHttpClient.execute(post);
+		try (CloseableHttpResponse response = ourHttpClient.execute(post)) {
-		try {
 			assertEquals(200, response.getStatusLine().getStatusCode());
-		} finally {
-			response.close();
 		}
 	}
 

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/StaleSearchDeletingSvcR4Test.java

@@ -2,6 +2,7 @@ package ca.uhn.fhir.jpa.provider.r4;
 
 import ca.uhn.fhir.jpa.entity.*;
 import ca.uhn.fhir.jpa.model.entity.ResourceTable;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.search.StaleSearchDeletingSvcImpl;
 import ca.uhn.fhir.rest.gclient.IClientExecutable;
 import ca.uhn.fhir.rest.gclient.IQuery;

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImplTest.java

@@ -7,7 +7,8 @@ import ca.uhn.fhir.jpa.dao.data.ISearchIncludeDao;
 import ca.uhn.fhir.jpa.dao.data.ISearchResultDao;
 import ca.uhn.fhir.jpa.entity.Search;
 import ca.uhn.fhir.jpa.entity.SearchResult;
-import ca.uhn.fhir.jpa.entity.SearchStatusEnum;
+import ca.uhn.fhir.jpa.model.interceptor.api.IInterceptorBroadcaster;
+import ca.uhn.fhir.jpa.model.search.SearchStatusEnum;
 import ca.uhn.fhir.jpa.entity.SearchTypeEnum;
 import ca.uhn.fhir.jpa.searchparam.SearchParameterMap;
 import ca.uhn.fhir.jpa.util.BaseIterator;
@@ -76,6 +77,8 @@ public class SearchCoordinatorSvcImplTest {
 	private Search myCurrentSearch;
 	@Mock
 	private DaoRegistry myDaoRegistry;
+	@Mock
+	private IInterceptorBroadcaster myInterceptorBroadcaster;
 
 	@After
 	public void after() {
@@ -94,6 +97,7 @@ public class SearchCoordinatorSvcImplTest {
 		mySvc.setSearchDaoIncludeForUnitTest(mySearchIncludeDao);
 		mySvc.setSearchDaoResultForUnitTest(mySearchResultDao);
 		mySvc.setDaoRegistryForUnitTest(myDaoRegistry);
+		mySvc.setInterceptorBroadcasterForUnitTest(myInterceptorBroadcaster);
 
 		myDaoConfig = new DaoConfig();
 		mySvc.setDaoConfigForUnitTest(myDaoConfig);
@@ -146,7 +150,7 @@ public class SearchCoordinatorSvcImplTest {
 
 		List<Long> pids = createPidSequence(10, 800);
 		IResultIterator iter = new FailAfterNIterator(new SlowIterator(pids.iterator(), 2), 300);
-		when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(iter);
+		when(mySearchBuider.createQuery(Mockito.same(params), any())).thenReturn(iter);
 
 		IBundleProvider result = mySvc.registerSearch(myCallingDao, params, "Patient", new CacheControlDirective());
 		assertNotNull(result.getUuid());
@@ -167,7 +171,7 @@ public class SearchCoordinatorSvcImplTest {
 
 		List<Long> pids = createPidSequence(10, 800);
 		SlowIterator iter = new SlowIterator(pids.iterator(), 1);
-		when(mySearchBuider.createQuery(any(), any(String.class))).thenReturn(iter);
+		when(mySearchBuider.createQuery(any(), any())).thenReturn(iter);
 		doAnswer(loadPids()).when(mySearchBuider).loadResourcesByPid(any(List.class), any(List.class), any(Set.class), anyBoolean(), any(EntityManager.class), any(FhirContext.class), same(myCallingDao));
 
 		when(mySearchResultDao.findWithSearchUuid(any(), any())).thenAnswer(t -> {
@@ -224,7 +228,7 @@ public class SearchCoordinatorSvcImplTest {
 
 		List<Long> pids = createPidSequence(10, 800);
 		SlowIterator iter = new SlowIterator(pids.iterator(), 2);
-		when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(iter);
+		when(mySearchBuider.createQuery(Mockito.same(params), any())).thenReturn(iter);
 
 		doAnswer(loadPids()).when(mySearchBuider).loadResourcesByPid(any(List.class), any(List.class), any(Set.class), anyBoolean(), any(EntityManager.class), any(FhirContext.class), same(myCallingDao));
 
@@ -252,7 +256,7 @@ public class SearchCoordinatorSvcImplTest {
 
 		List<Long> pids = createPidSequence(10, 800);
 		IResultIterator iter = new SlowIterator(pids.iterator(), 2);
-		when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(iter);
+		when(mySearchBuider.createQuery(Mockito.same(params), any())).thenReturn(iter);
 		when(mySearchDao.save(any())).thenAnswer(t -> t.getArguments()[0]);
 		doAnswer(loadPids()).when(mySearchBuider).loadResourcesByPid(any(List.class), any(List.class), any(Set.class), anyBoolean(), any(EntityManager.class), any(FhirContext.class), same(myCallingDao));
 
@@ -296,7 +300,7 @@ public class SearchCoordinatorSvcImplTest {
 
 		List<Long> pids = createPidSequence(10, 100);
 		SlowIterator iter = new SlowIterator(pids.iterator(), 2);
-		when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(iter);
+		when(mySearchBuider.createQuery(Mockito.same(params), any())).thenReturn(iter);
 
 		doAnswer(loadPids()).when(mySearchBuider).loadResourcesByPid(any(List.class), any(List.class), any(Set.class), anyBoolean(), any(EntityManager.class), any(FhirContext.class), same(myCallingDao));
 
@@ -385,7 +389,7 @@ public class SearchCoordinatorSvcImplTest {
 		params.add("name", new StringParam("ANAME"));
 
 		List<Long> pids = createPidSequence(10, 800);
-		when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(new ResultIterator(pids.iterator()));
+		when(mySearchBuider.createQuery(Mockito.same(params), any())).thenReturn(new ResultIterator(pids.iterator()));
 
 		doAnswer(loadPids()).when(mySearchBuider).loadResourcesByPid(eq(pids), any(List.class), any(Set.class), anyBoolean(), any(EntityManager.class), any(FhirContext.class), same(myCallingDao));
 
@@ -406,7 +410,7 @@ public class SearchCoordinatorSvcImplTest {
 		params.add("name", new StringParam("ANAME"));
 
 		List<Long> pids = createPidSequence(10, 800);
-		when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(new ResultIterator(pids.iterator()));
+		when(mySearchBuider.createQuery(Mockito.same(params), any())).thenReturn(new ResultIterator(pids.iterator()));
 
 		pids = createPidSequence(10, 110);
 		doAnswer(loadPids()).when(mySearchBuider).loadResourcesByPid(eq(pids), any(List.class), any(Set.class), anyBoolean(), any(EntityManager.class), any(FhirContext.class), same(myCallingDao));

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/subscription/resthook/RestHookTestDstu3Test.java

@@ -82,7 +82,7 @@ public class RestHookTestDstu3Test extends BaseResourceProviderDstu3Test {
 	@Before
 	public void beforeRegisterRestHookListener() {
 		mySubscriptionTestUtil.registerRestHookInterceptor();
-		myInterceptorRegistry.registerInterceptor(ourSubscriptionDebugLogInterceptor);
+		myInterceptorRegistry.registerAnonymousInterceptor(ourSubscriptionDebugLogInterceptor);
 	}
 
 	@Before

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/subscription/resthook/RestHookWithInterceptorR4Test.java

@@ -132,7 +132,7 @@ public class RestHookWithInterceptorR4Test extends BaseSubscriptionsR4Test {
 	@Test
 	public void testAttributesAreCopiedAlongPipeline() throws Exception {
 		AttributeCarryingInterceptor interceptor = new AttributeCarryingInterceptor();
-		myInterceptorRegistry.registerInterceptor(interceptor);
+		myInterceptorRegistry.registerAnonymousInterceptor(interceptor);
 		try {
 
 			// Create a subscription
@@ -191,7 +191,7 @@ public class RestHookWithInterceptorR4Test extends BaseSubscriptionsR4Test {
 		registerLatch.await(10, TimeUnit.SECONDS);
 
 		CountDownLatch latch = new CountDownLatch(1);
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.SUBSCRIPTION_AFTER_DELIVERY_FAILED, params -> {
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.SUBSCRIPTION_AFTER_DELIVERY_FAILED, (thePointcut, params) -> {
 			latch.countDown();
 		});
 
@@ -222,9 +222,9 @@ public class RestHookWithInterceptorR4Test extends BaseSubscriptionsR4Test {
 		}).when(loggerMock).debug(any(), ArgumentMatchers.<Object[]>any());
 
 		SubscriptionDebugLogInterceptor interceptor = new SubscriptionDebugLogInterceptor();
-		myInterceptorRegistry.registerInterceptor(interceptor);
+		myInterceptorRegistry.registerAnonymousInterceptor(interceptor);
 		SubscriptionDebugLogInterceptor interceptor2 = new SubscriptionDebugLogInterceptor(t -> loggerMock, Level.DEBUG);
-		myInterceptorRegistry.registerInterceptor(interceptor2);
+		myInterceptorRegistry.registerAnonymousInterceptor(interceptor2);
 		try {
 
 			String payload = "application/json";
@@ -310,7 +310,7 @@ public class RestHookWithInterceptorR4Test extends BaseSubscriptionsR4Test {
 		@Bean
 		public MyTestInterceptor interceptor() {
 			MyTestInterceptor retVal = new MyTestInterceptor();
-			myInterceptorRegistry.registerInterceptor(retVal);
+			myInterceptorRegistry.registerAnonymousInterceptor(retVal);
 			return retVal;
 		}
 

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/HookParams.java

@@ -23,10 +23,13 @@ package ca.uhn.fhir.jpa.model.interceptor.api;
 import com.google.common.collect.ArrayListMultimap;
 import com.google.common.collect.ListMultimap;
 import com.google.common.collect.Multimaps;
+import org.apache.commons.lang3.Validate;
 
 import java.util.Collection;
 import java.util.Collections;
 import java.util.List;
+import java.util.function.Supplier;
+import java.util.stream.Collectors;
 
 public class HookParams {
 
@@ -54,18 +57,45 @@ public class HookParams {
 	}
 
 	public <T> HookParams add(Class<T> theType, T theParam) {
+		return doAdd(theType, theParam);
+	}
+
+	/**
+	 * This is useful for providing a lazy-loaded (generally expensive to create)
+	 * parameters
+	 */
+	public <T> HookParams addSupplier(Class<T> theType, Supplier<T> theParam) {
+		return doAdd(theType, theParam);
+	}
+
+	private <T> HookParams doAdd(Class<T> theType, Object theParam) {
+		Validate.isTrue(theType.equals(Supplier.class) == false, "Can not add parameters of type Supplier");
 		myParams.put(theType, theParam);
 		return this;
 	}
 
+	public <T> T get(Class<T> theParamType) {
+		return get(theParamType, 0);
+	}
+
 		@SuppressWarnings("unchecked")
 	public <T> T get(Class<T> theParamType, int theIndex) {
-		List<T> objects = (List<T>) myParams.get(theParamType);
+		List<Object> objects = myParams.get(theParamType);
-		T retVal = null;
+		Object retVal = null;
 		if (objects.size() > theIndex) {
 			retVal = objects.get(theIndex);
 		}
-		return retVal;
+
+		retVal = unwrapValue(retVal);
+
+		return (T) retVal;
+	}
+
+	private Object unwrapValue(Object theValue) {
+		if (theValue instanceof Supplier) {
+			theValue = ((Supplier) theValue).get();
+		}
+		return theValue;
 	}
 
 	/**
@@ -73,10 +103,16 @@ public class HookParams {
 	 * key is the param type and the value is the actual instance
 	 */
 	public ListMultimap<Class<?>, Object> getParamsForType() {
-		return Multimaps.unmodifiableListMultimap(myParams);
+		ArrayListMultimap<Class<?>, Object> retVal = ArrayListMultimap.create();
+		myParams.entries().forEach(entry -> retVal.put(entry.getKey(), unwrapValue(entry.getValue())));
+		return Multimaps.unmodifiableListMultimap(retVal);
 	}
 
 	public Collection<Object> values() {
-		return Collections.unmodifiableCollection(myParams.values());
+		return
+			Collections.unmodifiableCollection(myParams.values())
+				.stream()
+				.map(t -> unwrapValue(t))
+				.collect(Collectors.toList());
 	}
 }

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/IAnonymousInterceptor.java

@@ -29,8 +29,8 @@ import com.google.common.annotations.VisibleForTesting;
  */
 @FunctionalInterface
 @VisibleForTesting
-public interface IAnonymousLambdaHook {
+public interface IAnonymousInterceptor {
 
-	void invoke(HookParams theArgs);
+	void invoke(Pointcut thePointcut, HookParams theArgs);
 
 }

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/IInterceptorRegistry.java

@@ -22,17 +22,44 @@ package ca.uhn.fhir.jpa.model.interceptor.api;
 
 import com.google.common.annotations.VisibleForTesting;
 
+import javax.annotation.Nullable;
+import java.util.Collection;
+
 public interface IInterceptorRegistry {
 
 	int DEFAULT_ORDER = 0;
 
+	/**
+	 * Register an interceptor that will be used in a {@link ThreadLocal} context.
+	 * This means that events will only be broadcast to the given interceptor if
+	 * they were fired from the current thread.
+	 * <p>
+	 * Note that it is almost always desirable to call this method with a
+	 * try-finally statment that removes the interceptor afterwards, since
+	 * this can lead to memory leakage, poor performance due to ever-increasing
+	 * numbers of interceptors, etc.
+	 * </p>
+	 *
+	 * @param theInterceptor The interceptor
+	 * @return Returns <code>true</code> if at least one valid hook method was found on this interceptor
+	 */
+	boolean registerThreadLocalInterceptor(Object theInterceptor);
+
+	/**
+	 * Unregisters a ThreadLocal interceptor
+	 *
+	 * @param theInterceptor The interceptor
+	 * @see #registerThreadLocalInterceptor(Object)
+	 */
+	void unregisterThreadLocalInterceptor(Object theInterceptor);
+
 	/**
 	 * Register an interceptor. This method has no effect if the given interceptor is already registered.
 	 *
 	 * @param theInterceptor The interceptor to register
 	 * @return Returns <code>true</code> if at least one valid hook method was found on this interceptor
 	 */
-	boolean registerInterceptor(Object theInterceptor);
+	boolean registerAnonymousInterceptor(Object theInterceptor);
 
 	/**
 	 * Unregister an interceptor. This method has no effect if the given interceptor is not already registered.
@@ -53,12 +80,12 @@ public interface IInterceptorRegistry {
 	@Deprecated
 	void unregisterGlobalInterceptor(Object theInterceptor);
 
-	@VisibleForTesting
+	void registerAnonymousInterceptor(Pointcut thePointcut, IAnonymousInterceptor theInterceptor);
-	void registerAnonymousHookForUnitTest(Pointcut thePointcut, IAnonymousLambdaHook theHook);
 
-	@VisibleForTesting
+	void registerAnonymousInterceptor(Pointcut thePointcut, int theOrder, IAnonymousInterceptor theInterceptor);
-	void registerAnonymousHookForUnitTest(Pointcut thePointcut, int theOrder, IAnonymousLambdaHook theHook);
 
 	@VisibleForTesting
 	void clearAnonymousHookForUnitTest();
+
+	void unregisterInterceptors(@Nullable Collection<?> theInterceptors);
 }

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/Pointcut.java

@@ -20,6 +20,9 @@ package ca.uhn.fhir.jpa.model.interceptor.api;
  * #L%
  */
 
+import ca.uhn.fhir.jpa.model.search.PerformanceMessage;
+import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
+
 import java.util.Arrays;
 import java.util.Collections;
 import java.util.List;
@@ -360,8 +363,137 @@ public enum Pointcut {
 	 * Hooks should return <code>void</code>.
 	 * </p>
 	 */
-	RESOURCE_MAY_BE_RETURNED("org.hl7.fhir.instance.model.api.IBaseResource");
+	RESOURCE_MAY_BE_RETURNED("org.hl7.fhir.instance.model.api.IBaseResource"),
 
+	/**
+	 * Note that this is a performance tracing hook. Use with caution in production
+	 * systems, since calling it may (or may not) carry a cost.
+	 * <p>
+	 * This hook is invoked when a search has returned the very first result
+	 * from the database. The timing on this call can be a good indicator of how
+	 * performant a query is in general.
+	 * </p>
+	 * Hooks may accept the following parameters:
+	 * <ul>
+	 * <li>
+	 * ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails - Contains details about the search being
+	 * performed. Hooks should not modify this object.
+	 * </li>
+	 * </ul>
+	 * <p>
+	 * Hooks should return <code>void</code>.
+	 * </p>
+	 */
+	PERFTRACE_SEARCH_FIRST_RESULT_LOADED(SearchRuntimeDetails.class.getName()),
+
+	/**
+	 * Note that this is a performance tracing hook. Use with caution in production
+	 * systems, since calling it may (or may not) carry a cost.
+	 * <p>
+	 * This hook is invoked when an individual search query SQL SELECT statement
+	 * has completed and no more results are available from that query. Note that this
+	 * doesn't necessarily mean that no more matching results exist in the database,
+	 * since HAPI FHIR JPA batch loads results in to the query cache in chunks in order
+	 * to provide predicable results without overloading memory or the database.
+	 * </p>
+	 * Hooks may accept the following parameters:
+	 * <ul>
+	 * <li>
+	 * ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails - Contains details about the search being
+	 * performed. Hooks should not modify this object.
+	 * </li>
+	 * </ul>
+	 * <p>
+	 * Hooks should return <code>void</code>.
+	 * </p>
+	 */
+	PERFTRACE_SEARCH_SELECT_COMPLETE(SearchRuntimeDetails.class.getName()),
+
+	/**
+	 * Note that this is a performance tracing hook. Use with caution in production
+	 * systems, since calling it may (or may not) carry a cost.
+	 * <p>
+	 * This hook is invoked when a search has failed for any reason. When this pointcut
+	 * is invoked, the search has completed unsuccessfully and will not be continued.
+	 * </p>
+	 * Hooks may accept the following parameters:
+	 * <ul>
+	 * <li>
+	 * ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails - Contains details about the search being
+	 * performed. Hooks should not modify this object.
+	 * </li>
+	 * </ul>
+	 * <p>
+	 * Hooks should return <code>void</code>.
+	 * </p>
+	 */
+	PERFTRACE_SEARCH_FAILED(SearchRuntimeDetails.class.getName()),
+
+	/**
+	 * Note that this is a performance tracing hook. Use with caution in production
+	 * systems, since calling it may (or may not) carry a cost.
+	 * <p>
+	 * This hook is invoked when a search has failed for any reason. When this pointcut
+	 * is invoked, a pass in the Search Coordinator has completed successfully, but
+	 * not all possible resources have been loaded yet so a future paging request
+	 * may trigger a new task that will load further resources.
+	 * </p>
+	 * Hooks may accept the following parameters:
+	 * <ul>
+	 * <li>
+	 * ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails - Contains details about the search being
+	 * performed. Hooks should not modify this object.
+	 * </li>
+	 * </ul>
+	 * <p>
+	 * Hooks should return <code>void</code>.
+	 * </p>
+	 */
+	PERFTRACE_SEARCH_PASS_COMPLETE(SearchRuntimeDetails.class.getName()),
+
+	/**
+	 * Note that this is a performance tracing hook. Use with caution in production
+	 * systems, since calling it may (or may not) carry a cost.
+	 * <p>
+	 * This hook is invoked when a search has failed for any reason. When this pointcut
+	 * is invoked, a pass in the Search Coordinator has completed successfully, and all
+	 * possible results have been fetched and loaded into the query cache.
+	 * </p>
+	 * Hooks may accept the following parameters:
+	 * <ul>
+	 * <li>
+	 * ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails - Contains details about the search being
+	 * performed. Hooks should not modify this object.
+	 * </li>
+	 * </ul>
+	 * <p>
+	 * Hooks should return <code>void</code>.
+	 * </p>
+	 */
+	PERFTRACE_SEARCH_COMPLETE(SearchRuntimeDetails.class.getName()),
+
+
+	/**
+	 * Note that this is a performance tracing hook. Use with caution in production
+	 * systems, since calling it may (or may not) carry a cost.
+	 * <p>
+	 * This hook is invoked when any informational or warning messages generated by the
+	 * SearchCoordinator are created. It is typically used to provide logging
+	 * or capture details related to a specific request.
+	 * </p>
+	 * Hooks may accept the following parameters:
+	 * <ul>
+	 * <li>
+	 * {@link PerformanceMessage} - Contains the message
+	 * </li>
+	 * </ul>
+	 * <p>
+	 * Hooks should return <code>void</code>.
+	 * </p>
+	 */
+	PERFTRACE_MESSAGE(PerformanceMessage.class.getName())
+
+	;
 	private final List<String> myParameterTypes;
 
 	Pointcut(String... theParameterTypes) {

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorService.java

@@ -25,15 +25,14 @@ import ca.uhn.fhir.rest.server.exceptions.InternalErrorException;
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.collect.ArrayListMultimap;
 import com.google.common.collect.ListMultimap;
+import com.google.common.collect.Multimaps;
 import com.google.common.collect.Sets;
-import org.apache.commons.collections4.ListUtils;
 import org.apache.commons.lang3.Validate;
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
 import org.springframework.core.annotation.AnnotationUtils;
 import org.springframework.core.annotation.Order;
 
 import javax.annotation.Nonnull;
+import javax.annotation.Nullable;
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.util.*;
@@ -41,22 +40,45 @@ import java.util.concurrent.atomic.AtomicInteger;
 import java.util.stream.Collectors;
 
 public class InterceptorService implements IInterceptorRegistry, IInterceptorBroadcaster {
-	private static final Logger ourLog = LoggerFactory.getLogger(InterceptorService.class);
 	private final List<Object> myInterceptors = new ArrayList<>();
-	private final ListMultimap<Pointcut, BaseInvoker> myInvokers = ArrayListMultimap.create();
+	private final ListMultimap<Pointcut, BaseInvoker> myGlobalInvokers = ArrayListMultimap.create();
 	private final ListMultimap<Pointcut, BaseInvoker> myAnonymousInvokers = ArrayListMultimap.create();
 	private final Object myRegistryMutex = new Object();
+	private final ThreadLocal<ListMultimap<Pointcut, BaseInvoker>> myThreadlocalInvokers = new ThreadLocal<>();
 	private String myName;
+	private boolean myThreadlocalInvokersEnabled = true;
+
+	/**
+	 * Constructor which uses a default name of "default"
+	 */
+	public InterceptorService() {
+		this("default");
+	}
 
 	/**
 	 * Constructor
-	 * @param theName
+	 *
+	 * @param theName The name for this registry (useful for troubleshooting)
 	 */
 	public InterceptorService(String theName) {
 		super();
 		myName = theName;
 	}
 
+	/**
+	 * Are threadlocal interceptors enabled on this registry (defaults to true)
+	 */
+	public boolean isThreadlocalInvokersEnabled() {
+		return myThreadlocalInvokersEnabled;
+	}
+
+	/**
+	 * Are threadlocal interceptors enabled on this registry (defaults to true)
+	 */
+	public void setThreadlocalInvokersEnabled(boolean theThreadlocalInvokersEnabled) {
+		myThreadlocalInvokersEnabled = theThreadlocalInvokersEnabled;
+	}
+
 	@VisibleForTesting
 	List<Object> getGlobalInterceptorsForUnitTest() {
 		return myInterceptors;
@@ -65,8 +87,8 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
 
 	@Override
 	@VisibleForTesting
-	public void registerAnonymousHookForUnitTest(Pointcut thePointcut, IAnonymousLambdaHook theHook) {
+	public void registerAnonymousInterceptor(Pointcut thePointcut, IAnonymousInterceptor theInterceptor) {
-		registerAnonymousHookForUnitTest(thePointcut, DEFAULT_ORDER, theHook);
+		registerAnonymousInterceptor(thePointcut, DEFAULT_ORDER, theInterceptor);
 	}
 
 	public void setName(String theName) {
@@ -74,94 +96,81 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
 	}
 
 	@Override
-	public void registerAnonymousHookForUnitTest(Pointcut thePointcut, int theOrder, IAnonymousLambdaHook theHook) {
+	public void registerAnonymousInterceptor(Pointcut thePointcut, int theOrder, IAnonymousInterceptor theInterceptor) {
 		Validate.notNull(thePointcut);
-		Validate.notNull(theHook);
+		Validate.notNull(theInterceptor);
-
+		synchronized (myRegistryMutex) {
-		myAnonymousInvokers.put(thePointcut, new AnonymousLambdaInvoker(theHook, theOrder));
+			myAnonymousInvokers.put(thePointcut, new AnonymousLambdaInvoker(thePointcut, theInterceptor, theOrder));
+		}
 	}
 
 	@Override
 	@VisibleForTesting
 	public void clearAnonymousHookForUnitTest() {
+		synchronized (myRegistryMutex) {
 			myAnonymousInvokers.clear();
 		}
+	}
 
 	@Override
-	public boolean registerInterceptor(Object theInterceptor) {
+	public void unregisterInterceptors(@Nullable Collection<?> theInterceptors) {
+		if (theInterceptors != null) {
+			theInterceptors.forEach(t -> unregisterInterceptor(t));
+		}
+	}
+
+	@Override
+	public boolean registerThreadLocalInterceptor(Object theInterceptor) {
+		if (!myThreadlocalInvokersEnabled) {
+			return false;
+		}
+		ListMultimap<Pointcut, BaseInvoker> invokers = getThreadLocalInvokerMultimap();
+		scanInterceptorAndAddToInvokerMultimap(theInterceptor, invokers);
+		return !invokers.isEmpty();
+
+	}
+
+	@Override
+	public void unregisterThreadLocalInterceptor(Object theInterceptor) {
+		if (myThreadlocalInvokersEnabled) {
+			ListMultimap<Pointcut, BaseInvoker> invokers = getThreadLocalInvokerMultimap();
+			invokers.entries().removeIf(t -> t.getValue().getInterceptor() == theInterceptor);
+			if (invokers.isEmpty()) {
+				myThreadlocalInvokers.remove();
+			}
+		}
+	}
+
+	private ListMultimap<Pointcut, BaseInvoker> getThreadLocalInvokerMultimap() {
+		ListMultimap<Pointcut, BaseInvoker> invokers = myThreadlocalInvokers.get();
+		if (invokers == null) {
+			invokers = Multimaps.synchronizedListMultimap(ArrayListMultimap.create());
+			myThreadlocalInvokers.set(invokers);
+		}
+		return invokers;
+	}
+
+	@Override
+	public boolean registerAnonymousInterceptor(Object theInterceptor) {
 		synchronized (myRegistryMutex) {
 
 			if (isInterceptorAlreadyRegistered(theInterceptor)) {
 				return false;
 			}
 
-			Class<?> interceptorClass = theInterceptor.getClass();
+			List<HookInvoker> addedInvokers = scanInterceptorAndAddToInvokerMultimap(theInterceptor, myGlobalInvokers);
-			int typeOrder = determineOrder(interceptorClass);
-
-			List<HookInvoker> addedInvokers = scanInterceptorForHookMethods(theInterceptor, typeOrder);
 			if (addedInvokers.isEmpty()) {
 				return false;
 			}
 
-			// Invoke the REGISTERED pointcut for any added hooks
+			// Add to the global list
-			addedInvokers.stream()
-				.filter(t -> t.getPointcuts().contains(Pointcut.REGISTERED))
-				.forEach(t -> t.invoke(new HookParams()));
-
-			// Register the interceptor and its various hooks
 			myInterceptors.add(theInterceptor);
-			for (HookInvoker nextAddedHook : addedInvokers) {
-				for (Pointcut nextPointcut : nextAddedHook.getPointcuts()) {
-					if (nextPointcut.equals(Pointcut.REGISTERED)) {
-						continue;
-					}
-					myInvokers.put(nextPointcut, nextAddedHook);
-				}
-			}
-
-			// Make sure we're always sorted according to the order declared in
-			// @Order
 			sortByOrderAnnotation(myInterceptors);
-			for (Pointcut nextPointcut : myInvokers.keys()) {
-				List<BaseInvoker> nextInvokerList = myInvokers.get(nextPointcut);
-				nextInvokerList.sort(Comparator.naturalOrder());
-			}
 
 			return true;
 		}
 	}
 
-	/**
-	 * @return Returns a list of any added invokers
-	 */
-	private List<HookInvoker> scanInterceptorForHookMethods(Object theInterceptor, int theTypeOrder) {
-		ArrayList<HookInvoker> retVal = new ArrayList<>();
-		for (Method nextMethod : theInterceptor.getClass().getMethods()) {
-			Hook hook = AnnotationUtils.findAnnotation(nextMethod, Hook.class);
-
-			if (hook != null) {
-				int methodOrder = theTypeOrder;
-				Order methodOrderAnnotation = AnnotationUtils.findAnnotation(nextMethod, Order.class);
-				if (methodOrderAnnotation != null) {
-					methodOrder = methodOrderAnnotation.value();
-				}
-
-				retVal.add(new HookInvoker(hook, theInterceptor, nextMethod, methodOrder));
-			}
-		}
-
-		return retVal;
-	}
-
-	private int determineOrder(Class<?> theInterceptorClass) {
-		int typeOrder = DEFAULT_ORDER;
-		Order typeOrderAnnotation = AnnotationUtils.findAnnotation(theInterceptorClass, Order.class);
-		if (typeOrderAnnotation != null) {
-			typeOrder = typeOrderAnnotation.value();
-		}
-		return typeOrder;
-	}
-
 	private boolean isInterceptorAlreadyRegistered(Object theInterceptor) {
 		for (Object next : myInterceptors) {
 			if (next == theInterceptor) {
@@ -175,13 +184,14 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
 	public void unregisterInterceptor(Object theInterceptor) {
 		synchronized (myRegistryMutex) {
 			myInterceptors.removeIf(t -> t == theInterceptor);
-			myInvokers.entries().removeIf(t -> t.getValue().getInterceptor() == theInterceptor);
+			myGlobalInvokers.entries().removeIf(t -> t.getValue().getInterceptor() == theInterceptor);
+			myAnonymousInvokers.entries().removeIf(t -> t.getValue().getInterceptor() == theInterceptor);
 		}
 	}
 
 	@Override
 	public boolean registerGlobalInterceptor(Object theInterceptor) {
-		return registerInterceptor(theInterceptor);
+		return registerAnonymousInterceptor(theInterceptor);
 	}
 
 	@Override
@@ -242,20 +252,72 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
 	 */
 	private List<BaseInvoker> getInvokersForPointcut(Pointcut thePointcut) {
 		List<BaseInvoker> invokers;
-		boolean haveAnonymousInvokers;
+
 		synchronized (myRegistryMutex) {
-			List<BaseInvoker> globalInvokers = myInvokers.get(thePointcut);
+			List<BaseInvoker> globalInvokers = myGlobalInvokers.get(thePointcut);
 			List<BaseInvoker> anonymousInvokers = myAnonymousInvokers.get(thePointcut);
-			invokers = ListUtils.union(anonymousInvokers, globalInvokers);
+			List<BaseInvoker> threadLocalInvokers = null;
-			haveAnonymousInvokers = anonymousInvokers.isEmpty() == false;
+			if (myThreadlocalInvokersEnabled) {
+				ListMultimap<Pointcut, BaseInvoker> pointcutToInvokers = myThreadlocalInvokers.get();
+				if (pointcutToInvokers != null) {
+					threadLocalInvokers = pointcutToInvokers.get(thePointcut);
+				}
+			}
+			invokers = union(globalInvokers, anonymousInvokers, threadLocalInvokers);
 		}
 
-		if (haveAnonymousInvokers) {
-			invokers.sort(Comparator.naturalOrder());
-		}
 		return invokers;
 	}
 
+	/**
+	 * First argument must be the global invoker list!!
+	 */
+	private List<BaseInvoker> union(List<BaseInvoker>... theInvokersLists) {
+		List<BaseInvoker> haveOne = null;
+		boolean haveMultiple = false;
+		for (List<BaseInvoker> nextInvokerList : theInvokersLists) {
+			if (nextInvokerList == null || nextInvokerList.isEmpty()) {
+				continue;
+			}
+
+			if (haveOne == null) {
+				haveOne = nextInvokerList;
+			} else {
+				haveMultiple = true;
+			}
+		}
+
+		if (haveOne == null) {
+			return Collections.emptyList();
+		}
+
+		List<BaseInvoker> retVal;
+
+		if (haveMultiple == false) {
+
+			// The global list doesn't need to be sorted every time since it's sorted on
+			// insertion each time. Doing so is a waste of cycles..
+			if (haveOne == theInvokersLists[0]) {
+				retVal = haveOne;
+			} else {
+				retVal = new ArrayList<>(haveOne);
+				retVal.sort(Comparator.naturalOrder());
+			}
+
+		} else {
+
+			retVal = Arrays
+				.stream(theInvokersLists)
+				.filter(t -> t != null)
+				.flatMap(t -> t.stream())
+				.sorted()
+				.collect(Collectors.toList());
+
+		}
+
+		return retVal;
+	}
+
 	/**
 	 * Only call this when assertions are enabled, it's expensive
 	 */
@@ -276,7 +338,24 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
 		return true;
 	}
 
-	private abstract class BaseInvoker implements Comparable<BaseInvoker> {
+	private class AnonymousLambdaInvoker extends BaseInvoker {
+		private final IAnonymousInterceptor myHook;
+		private final Pointcut myPointcut;
+
+		public AnonymousLambdaInvoker(Pointcut thePointcut, IAnonymousInterceptor theHook, int theOrder) {
+			super(theHook, theOrder);
+			myHook = theHook;
+			myPointcut = thePointcut;
+		}
+
+		@Override
+		boolean invoke(HookParams theParams) {
+			myHook.invoke(myPointcut, theParams);
+			return true;
+		}
+	}
+
+	private abstract static class BaseInvoker implements Comparable<BaseInvoker> {
 
 		private final int myOrder;
 		private final Object myInterceptor;
@@ -293,27 +372,12 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
 		abstract boolean invoke(HookParams theParams);
 
 		@Override
-		public int compareTo(BaseInvoker o) {
+		public int compareTo(BaseInvoker theInvoker) {
-			return myOrder - o.myOrder;
+			return myOrder - theInvoker.myOrder;
 		}
 	}
 
-	private class AnonymousLambdaInvoker extends BaseInvoker {
+	private static class HookInvoker extends BaseInvoker {
-		private final IAnonymousLambdaHook myHook;
-
-		public AnonymousLambdaInvoker(IAnonymousLambdaHook theHook, int theOrder) {
-			super(theHook, theOrder);
-			myHook = theHook;
-		}
-
-		@Override
-		boolean invoke(HookParams theParams) {
-			myHook.invoke(theParams);
-			return true;
-		}
-	}
-
-	private class HookInvoker extends BaseInvoker {
 
 		private final boolean myReturnsBoolean;
 		private final Method myMethod;
@@ -387,6 +451,68 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
 
 	}
 
+	private static List<HookInvoker> scanInterceptorAndAddToInvokerMultimap(Object theInterceptor, ListMultimap<Pointcut, BaseInvoker> theInvokers) {
+		Class<?> interceptorClass = theInterceptor.getClass();
+		int typeOrder = determineOrder(interceptorClass);
+
+		List<HookInvoker> addedInvokers = scanInterceptorForHookMethods(theInterceptor, typeOrder);
+
+		// Invoke the REGISTERED pointcut for any added hooks
+		addedInvokers.stream()
+			.filter(t -> t.getPointcuts().contains(Pointcut.REGISTERED))
+			.forEach(t -> t.invoke(new HookParams()));
+
+		// Register the interceptor and its various hooks
+		for (HookInvoker nextAddedHook : addedInvokers) {
+			for (Pointcut nextPointcut : nextAddedHook.getPointcuts()) {
+				if (nextPointcut.equals(Pointcut.REGISTERED)) {
+					continue;
+				}
+				theInvokers.put(nextPointcut, nextAddedHook);
+			}
+		}
+
+		// Make sure we're always sorted according to the order declared in
+		// @Order
+		for (Pointcut nextPointcut : theInvokers.keys()) {
+			List<BaseInvoker> nextInvokerList = theInvokers.get(nextPointcut);
+			nextInvokerList.sort(Comparator.naturalOrder());
+		}
+
+		return addedInvokers;
+	}
+
+	/**
+	 * @return Returns a list of any added invokers
+	 */
+	private static List<HookInvoker> scanInterceptorForHookMethods(Object theInterceptor, int theTypeOrder) {
+		ArrayList<HookInvoker> retVal = new ArrayList<>();
+		for (Method nextMethod : theInterceptor.getClass().getMethods()) {
+			Hook hook = AnnotationUtils.findAnnotation(nextMethod, Hook.class);
+
+			if (hook != null) {
+				int methodOrder = theTypeOrder;
+				Order methodOrderAnnotation = AnnotationUtils.findAnnotation(nextMethod, Order.class);
+				if (methodOrderAnnotation != null) {
+					methodOrder = methodOrderAnnotation.value();
+				}
+
+				retVal.add(new HookInvoker(hook, theInterceptor, nextMethod, methodOrder));
+			}
+		}
+
+		return retVal;
+	}
+
+	private static int determineOrder(Class<?> theInterceptorClass) {
+		int typeOrder = DEFAULT_ORDER;
+		Order typeOrderAnnotation = AnnotationUtils.findAnnotation(theInterceptorClass, Order.class);
+		if (typeOrderAnnotation != null) {
+			typeOrder = typeOrderAnnotation.value();
+		}
+		return typeOrder;
+	}
+
 	private static String toErrorString(List<String> theParameterTypes) {
 		return theParameterTypes
 			.stream()

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/IndexNonDeletedInterceptor.java

@@ -25,6 +25,10 @@ import org.hibernate.search.indexes.interceptor.EntityIndexingInterceptor;
 import org.hibernate.search.indexes.interceptor.IndexingOverride;
 
 /**
+ * Note that this is a Hibernate Search interceptor, not a HAPI FHIR interceptor.
+ * It's used in {@link ResourceTable}. There is no reason for this to be used
+ * in any user code.
+ *
  * Only store non-deleted resources
  */
 public class IndexNonDeletedInterceptor implements EntityIndexingInterceptor<ResourceTable> {

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/PerformanceMessage.java

@@ -0,0 +1,16 @@
+package ca.uhn.fhir.jpa.model.search;
+
+public class PerformanceMessage {
+
+	private String myMessage;
+
+	public String getMessage() {
+		return myMessage;
+	}
+
+	public PerformanceMessage setMessage(String theMessage) {
+		myMessage = theMessage;
+		return this;
+	}
+
+}

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/SearchRuntimeDetails.java

@@ -0,0 +1,64 @@
+package ca.uhn.fhir.jpa.model.search;
+
+import ca.uhn.fhir.util.StopWatch;
+
+/**
+ * This class contains a runtime in-memory description of a search operation,
+ * including details on processing time and other things
+ */
+public class SearchRuntimeDetails {
+	private final String mySearchUuid;
+	private StopWatch myQueryStopwatch;
+	private int myFoundMatchesCount;
+	private boolean myLoadSynchronous;
+	private String myQueryString;
+	private SearchStatusEnum mySearchStatus;
+
+	public SearchRuntimeDetails(String theSearchUuid) {
+		mySearchUuid = theSearchUuid;
+	}
+
+	public String getSearchUuid() {
+		return mySearchUuid;
+	}
+
+	public StopWatch getQueryStopwatch() {
+		return myQueryStopwatch;
+	}
+
+	public void setQueryStopwatch(StopWatch theQueryStopwatch) {
+		myQueryStopwatch = theQueryStopwatch;
+	}
+
+	public void setFoundMatchesCount(int theFoundMatchesCount) {
+		myFoundMatchesCount = theFoundMatchesCount;
+	}
+
+	public int getFoundMatchesCount() {
+		return myFoundMatchesCount;
+	}
+
+	public void setLoadSynchronous(boolean theLoadSynchronous) {
+		myLoadSynchronous = theLoadSynchronous;
+	}
+
+	public boolean getLoadSynchronous() {
+		return myLoadSynchronous;
+	}
+
+	public void setQueryString(String theQueryString) {
+		myQueryString = theQueryString;
+	}
+
+	public String getQueryString() {
+		return myQueryString;
+	}
+
+	public SearchStatusEnum getSearchStatus() {
+		return mySearchStatus;
+	}
+
+	public void setSearchStatus(SearchStatusEnum theSearchStatus) {
+		mySearchStatus = theSearchStatus;
+	}
+}

hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/SearchStatusEnum.java

@@ -1,4 +1,4 @@
-package ca.uhn.fhir.jpa.entity;
+package ca.uhn.fhir.jpa.model.search;
 
 /*-
  * #%L

hapi-fhir-jpaserver-model/src/test/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorServiceTest.java

@@ -1,15 +1,22 @@
 package ca.uhn.fhir.jpa.model.interceptor.executor;
 
-import ca.uhn.fhir.jpa.model.interceptor.api.*;
+import ca.uhn.fhir.jpa.model.interceptor.api.Hook;
+import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
+import ca.uhn.fhir.jpa.model.interceptor.api.Interceptor;
+import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
 import ca.uhn.fhir.rest.server.exceptions.InternalErrorException;
+import ca.uhn.fhir.util.StopWatch;
 import org.hl7.fhir.instance.model.api.IBaseResource;
 import org.hl7.fhir.r4.model.Patient;
+import org.junit.After;
 import org.junit.Before;
+import org.junit.Ignore;
 import org.junit.Test;
 import org.junit.runner.RunWith;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.context.annotation.Bean;
-import org.springframework.context.annotation.ComponentScan;
 import org.springframework.context.annotation.Configuration;
 import org.springframework.core.annotation.Order;
 import org.springframework.test.context.ContextConfiguration;
@@ -25,15 +32,14 @@ import static org.junit.Assert.*;
 @ContextConfiguration(classes = {InterceptorServiceTest.InterceptorRegistryTestCtxConfig.class})
 public class InterceptorServiceTest {
 
+	private static final Logger ourLog = LoggerFactory.getLogger(InterceptorServiceTest.class);
 	private static boolean ourNext_beforeRestHookDelivery_Return1;
 	private static List<String> ourInvocations = new ArrayList<>();
 	private static IBaseResource ourLastResourceOne;
 	private static IBaseResource ourLastResourceTwoA;
 	private static IBaseResource ourLastResourceTwoB;
-
 	@Autowired
 	private InterceptorService myInterceptorRegistry;
-
 	@Autowired
 	private MyTestInterceptorOne myInterceptorOne;
 	@Autowired
@@ -46,7 +52,7 @@ public class InterceptorServiceTest {
 		int initialSize = myInterceptorRegistry.getGlobalInterceptorsForUnitTest().size();
 
 		try {
-			myInterceptorRegistry.registerInterceptor(new InterceptorThatFailsOnRegister());
+			myInterceptorRegistry.registerAnonymousInterceptor(new InterceptorThatFailsOnRegister());
 			fail();
 		} catch (InternalErrorException e) {
 			// good
@@ -68,7 +74,7 @@ public class InterceptorServiceTest {
 	public void testManuallyRegisterGlobalInterceptor() {
 
 		// Register the manual interceptor (has @Order right in the middle)
-		myInterceptorRegistry.registerInterceptor(myInterceptorManual);
+		myInterceptorRegistry.registerAnonymousInterceptor(myInterceptorManual);
 		List<Object> globalInterceptors = myInterceptorRegistry.getGlobalInterceptorsForUnitTest();
 		assertEquals(3, globalInterceptors.size());
 		assertTrue(globalInterceptors.get(0).getClass().toString(), globalInterceptors.get(0) instanceof MyTestInterceptorOne);
@@ -76,7 +82,7 @@ public class InterceptorServiceTest {
 		assertTrue(globalInterceptors.get(2).getClass().toString(), globalInterceptors.get(2) instanceof MyTestInterceptorTwo);
 
 		// Try to register again (should have no effect
-		myInterceptorRegistry.registerInterceptor(myInterceptorManual);
+		myInterceptorRegistry.registerAnonymousInterceptor(myInterceptorManual);
 		globalInterceptors = myInterceptorRegistry.getGlobalInterceptorsForUnitTest();
 		assertEquals(3, globalInterceptors.size());
 		assertTrue(globalInterceptors.get(0).getClass().toString(), globalInterceptors.get(0) instanceof MyTestInterceptorOne);
@@ -112,6 +118,20 @@ public class InterceptorServiceTest {
 		assertSame(patient, ourLastResourceOne);
 	}
 
+	@Test
+	public void testInvokeUsingSupplierArg() {
+		Patient patient = new Patient();
+		HookParams params = new HookParams()
+			.addSupplier(IBaseResource.class, () -> patient);
+		boolean outcome = myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+		assertTrue(outcome);
+
+		assertThat(ourInvocations, contains("MyTestInterceptorOne.beforeRestHookDelivery", "MyTestInterceptorTwo.beforeRestHookDelivery"));
+		assertSame(patient, ourLastResourceTwoA);
+		assertNull(ourLastResourceTwoB);
+		assertSame(patient, ourLastResourceOne);
+	}
+
 	@Test
 	public void testInvokeGlobalInterceptorMethods_MethodAbortsProcessing() {
 		ourNext_beforeRestHookDelivery_Return1 = false;
@@ -188,6 +208,113 @@ public class InterceptorServiceTest {
 		}
 	}
 
+	@Test
+	public void testThreadLocalHookInterceptor() {
+		myInterceptorRegistry.setThreadlocalInvokersEnabled(true);
+
+		Patient patient = new Patient();
+		HookParams params = new HookParams().add(IBaseResource.class, patient);
+
+		@Interceptor
+		@Order(100)
+		class LocalInterceptor {
+
+			private int myCount = 0;
+
+			@Hook(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED)
+			public boolean beforeRestHookDelivery(IBaseResource theResource) {
+				myCount++;
+				return true;
+			}
+
+		}
+		LocalInterceptor interceptor = new LocalInterceptor();
+		myInterceptorRegistry.registerThreadLocalInterceptor(interceptor);
+		try {
+
+			myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+			myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+			myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+			myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+			myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+			assertEquals(5, interceptor.myCount);
+
+		} finally {
+			myInterceptorRegistry.unregisterThreadLocalInterceptor(interceptor);
+		}
+
+		// Call some more - The interceptor is removed so the count shouldn't change
+		myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+		myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+		myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+		myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+		myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+		assertEquals(5, interceptor.myCount);
+
+	}
+
+	/**
+	 * <pre>
+	 * JA 20190321 On my MBP 2018
+	 *    ThreadLocalEnabled=true - Performed 500000 loops in 8383.0ms - 0.017ms / loop
+	 *    ThreadLocalEnabled=false - Performed 500000 loops in 3743.0ms - 0.007ms / loop
+	 *    ThreadLocalEnabled=true - Performed 500000 loops in 6163.0ms - 0.012ms / loop
+	 *    ThreadLocalEnabled=false - Performed 500000 loops in 3487.0ms - 0.007ms / loop
+	 *    ThreadLocalEnabled=true - Performed 1000000 loops in 00:00:12.458 - 0.012ms / loop
+	 *    ThreadLocalEnabled=false - Performed 1000000 loops in 7046.0ms - 0.007ms / loop
+	 * </pre>
+	 */
+	@Test
+	@Ignore("Performance test - Not needed normally")
+	public void testThreadLocalHookInterceptorMicroBenchmark() {
+		threadLocalMicroBenchmark(true, 500000);
+		threadLocalMicroBenchmark(false, 500000);
+		threadLocalMicroBenchmark(true, 500000);
+		threadLocalMicroBenchmark(false, 500000);
+		threadLocalMicroBenchmark(true, 1000000);
+		threadLocalMicroBenchmark(false, 1000000);
+	}
+
+	private void threadLocalMicroBenchmark(boolean theThreadlocalInvokersEnabled, int theCount) {
+		myInterceptorRegistry.setThreadlocalInvokersEnabled(theThreadlocalInvokersEnabled);
+
+		Patient patient = new Patient();
+		HookParams params = new HookParams().add(IBaseResource.class, patient);
+
+		@Interceptor
+		@Order(100)
+		class LocalInterceptor {
+
+			private int myCount = 0;
+
+			@Hook(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED)
+			public boolean beforeRestHookDelivery(IBaseResource theResource) {
+				myCount++;
+				return true;
+			}
+
+		}
+
+		StopWatch sw = new StopWatch();
+		for (int i = 0; i < theCount; i++) {
+
+			LocalInterceptor interceptor = new LocalInterceptor();
+			myInterceptorRegistry.registerThreadLocalInterceptor(interceptor);
+			try {
+				myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+				myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+				myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+				myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+				myInterceptorRegistry.callHooks(Pointcut.OP_PRECOMMIT_RESOURCE_CREATED, params);
+			} finally {
+				myInterceptorRegistry.unregisterThreadLocalInterceptor(interceptor);
+			}
+
+		}
+
+		ourLog.info("ThreadLocalEnabled={} - Performed {} loops in {} - {} / loop", theThreadlocalInvokersEnabled, theCount, sw.toString(), sw.formatMillisPerOperation(theCount));
+	}
+
 	@Before
 	public void before() {
 		ourNext_beforeRestHookDelivery_Return1 = true;
@@ -197,8 +324,12 @@ public class InterceptorServiceTest {
 		ourInvocations.clear();
 	}
 
+	@After
+	public void after() {
+		myInterceptorRegistry.setThreadlocalInvokersEnabled(new InterceptorService().isThreadlocalInvokersEnabled());
+	}
+
 	@Configuration
-	@ComponentScan(basePackages = "ca.uhn.fhir.jpa.model")
 	static class InterceptorRegistryTestCtxConfig {
 
 		@Bean
@@ -213,7 +344,7 @@ public class InterceptorServiceTest {
 		@Bean
 		public MyTestInterceptorTwo interceptor1() {
 			MyTestInterceptorTwo retVal = new MyTestInterceptorTwo();
-			interceptorService().registerInterceptor(retVal);
+			interceptorService().registerAnonymousInterceptor(retVal);
 			return retVal;
 		}
 
@@ -224,7 +355,7 @@ public class InterceptorServiceTest {
 		@Bean
 		public MyTestInterceptorOne interceptor2() {
 			MyTestInterceptorOne retVal = new MyTestInterceptorOne();
-			interceptorService().registerInterceptor(retVal);
+			interceptorService().registerAnonymousInterceptor(retVal);
 			return retVal;
 		}
 

hapi-fhir-jpaserver-searchparam/src/main/java/ca/uhn/fhir/jpa/searchparam/SearchParameterMap.java

@@ -373,7 +373,6 @@ public class SearchParameterMap implements Serializable {
 						b.append(',');
 					}
 					String valueAsQueryToken = nextValueOr.getValueAsQueryToken(theCtx);
-//					b.append(ParameterUtil.escapeAndUrlEncode(valueAsQueryToken));
 					b.append(UrlUtil.escapeUrlParam(valueAsQueryToken));
 				}
 			}

hapi-fhir-jpaserver-subscription/src/test/java/ca/uhn/fhir/jpa/subscription/module/PointcutLatch.java

@@ -1,7 +1,7 @@
 package ca.uhn.fhir.jpa.subscription.module;
 
 import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
-import ca.uhn.fhir.jpa.model.interceptor.api.IAnonymousLambdaHook;
+import ca.uhn.fhir.jpa.model.interceptor.api.IAnonymousInterceptor;
 import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
@@ -15,7 +15,7 @@ import java.util.stream.Collectors;
 
 import static org.junit.Assert.*;
 
-public class PointcutLatch implements IAnonymousLambdaHook {
+public class PointcutLatch implements IAnonymousInterceptor {
 	private static final Logger ourLog = LoggerFactory.getLogger(PointcutLatch.class);
 	private static final int DEFAULT_TIMEOUT_SECONDS = 10;
 	private static final FhirObjectPrinter ourFhirObjectToStringMapper = new FhirObjectPrinter();
@@ -25,9 +25,11 @@ public class PointcutLatch implements IAnonymousLambdaHook {
 	private CountDownLatch myCountdownLatch;
 	private AtomicReference<String> myFailure;
 	private AtomicReference<List<HookParams>> myCalledWith;
+	private Pointcut myPointcut;
 
 	public PointcutLatch(Pointcut thePointcut) {
 		this.name = thePointcut.name();
+		myPointcut = thePointcut;
 	}
 
 	public PointcutLatch(String theName) {
@@ -105,7 +107,7 @@ public class PointcutLatch implements IAnonymousLambdaHook {
 
 
 	@Override
-	public void invoke(HookParams theArgs) {
+	public void invoke(Pointcut thePointcut, HookParams theArgs) {
 		if (myCountdownLatch == null) {
 			throw new PointcutLatchException("invoke() called before setExpectedCount() called.", theArgs);
 		} else if (myCountdownLatch.getCount() <= 0) {
@@ -121,7 +123,7 @@ public class PointcutLatch implements IAnonymousLambdaHook {
 	}
 
 	public void call(Object arg) {
-		this.invoke(new HookParams(arg));
+		this.invoke(myPointcut, new HookParams(arg));
 	}
 
 	private class PointcutLatchException extends IllegalStateException {

hapi-fhir-jpaserver-subscription/src/test/java/ca/uhn/fhir/jpa/subscription/module/standalone/BaseBlockingQueueSubscribableChannelDstu3Test.java

@@ -78,8 +78,8 @@ public abstract class BaseBlockingQueueSubscribableChannelDstu3Test extends Base
 			ourSubscribableChannel = mySubscriptionChannelFactory.newDeliveryChannel("test", Subscription.SubscriptionChannelType.RESTHOOK.toCode().toLowerCase());
 			ourSubscribableChannel.subscribe(myStandaloneSubscriptionMessageHandler);
 		}
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.SUBSCRIPTION_AFTER_PERSISTED_RESOURCE_CHECKED, mySubscriptionMatchingPost);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.SUBSCRIPTION_AFTER_PERSISTED_RESOURCE_CHECKED, mySubscriptionMatchingPost);
-		myInterceptorRegistry.registerAnonymousHookForUnitTest(Pointcut.SUBSCRIPTION_AFTER_ACTIVE_SUBSCRIPTION_REGISTERED, mySubscriptionActivatedPost);
+		myInterceptorRegistry.registerAnonymousInterceptor(Pointcut.SUBSCRIPTION_AFTER_ACTIVE_SUBSCRIPTION_REGISTERED, mySubscriptionActivatedPost);
 	}
 
 	@After
@@ -171,7 +171,7 @@ public abstract class BaseBlockingQueueSubscribableChannelDstu3Test extends Base
 		public MethodOutcome update(@ResourceParam Observation theObservation, HttpServletRequest theRequest) {
 			ourContentTypes.add(theRequest.getHeader(Constants.HEADER_CONTENT_TYPE).replaceAll(";.*", ""));
 			ourUpdatedObservations.add(theObservation);
-			updateLatch.invoke(new HookParams().add(Observation.class, theObservation));
+			updateLatch.invoke(null, new HookParams().add(Observation.class, theObservation));
 			ourLog.info("Received Listener Update (now have {} updates)", ourUpdatedObservations.size());
 			return new MethodOutcome(new IdType("Observation/1"), false);
 		}

pom.xml

@@ -2266,7 +2266,6 @@
 				<module>hapi-fhir-jaxrsserver-example</module>
 				<module>hapi-fhir-jpaserver-base</module>
 				<module>hapi-fhir-jpaserver-elasticsearch</module>
-				<module>hapi-fhir-jpaserver-example</module>
 				<module>hapi-fhir-jpaserver-migrate</module>
 				<module>restful-server-example</module>
 				<module>restful-server-example-test</module>

src/changes/changes.xml

@@ -105,6 +105,9 @@
 				a REFERENCE search parameter was used with arguments that consisted of
 				unqualified resource IDs.
 			</action>
+			<action type="fix">
+				A non-threadsafe use of DateFormat was cleaned up in the StopWatch class.
+			</action>
 			<action type="add">
 				When performing a search in the JPA server where one of the parameters is a
 				reference with multiple values (e.g. Patient?organization=A,B) the generated