diff --git a/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/LogUtil.java b/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/LogUtil.java new file mode 100644 index 00000000000..e68a2b0ef9a --- /dev/null +++ b/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/LogUtil.java @@ -0,0 +1,31 @@ +package ca.uhn.fhir.util; + +import org.slf4j.Logger; + +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; + } + } + + public enum Level { + TRACE, DEBUG, INFO, WARN, ERROR + } + +} diff --git a/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java b/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java index 2a2e68b626e..e46907aa54d 100644 --- a/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java +++ b/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; @@ -21,9 +20,9 @@ import static org.apache.commons.lang3.StringUtils.isNotBlank; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -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 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. - *

- * Example outputs: - *

- * - */ - 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. + *

+ * Example outputs: + *

+ * + */ + 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. + *

+ * Example outputs: + *

+ * + */ + 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; + } + } diff --git a/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/LogUtilTest.java b/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/LogUtilTest.java new file mode 100644 index 00000000000..28d345fc0af --- /dev/null +++ b/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/LogUtilTest.java @@ -0,0 +1,28 @@ +package ca.uhn.fhir.util; + +import org.junit.Test; +import org.slf4j.Logger; + +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, LogUtil.Level.TRACE, "HELLO"); + LogUtil.log(log, LogUtil.Level.DEBUG, "HELLO"); + LogUtil.log(log, LogUtil.Level.INFO, "HELLO"); + LogUtil.log(log, LogUtil.Level.WARN, "HELLO"); + LogUtil.log(log, LogUtil.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); + } + +} diff --git a/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java b/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java index 299290c1c39..1aaa20e5637 100644 --- a/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java +++ b/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)); diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java index f5575c693ca..64571137874 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java +++ b/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; @@ -1131,7 +1132,9 @@ public abstract class BaseHapiFhirResourceDao extends B HashSet retVal = new HashSet(); String uuid = UUID.randomUUID().toString(); - Iterator iter = builder.createQuery(theParams, uuid); + SearchRuntimeDetails searchRuntimeDetails = new SearchRuntimeDetails(uuid); + + Iterator iter = builder.createQuery(theParams, searchRuntimeDetails); while (iter.hasNext()) { retVal.add(iter.next()); } diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/ISearchBuilder.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/ISearchBuilder.java index 6d59176bba9..3e9aeb3915c 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/ISearchBuilder.java +++ b/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); diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java index 604fb8f1500..d34d048cf0f 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java +++ b/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 myAlsoIncludePids; private CriteriaBuilder myBuilder; private BaseHapiFhirDao myCallingDao; @@ -1524,10 +1525,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; @@ -1539,7 +1540,7 @@ public class SearchBuilder implements ISearchBuilder { myPidSet = new HashSet<>(); } - return new QueryIterator(); + return new QueryIterator(theSearchRuntimeDetails); } private TypedQuery createQuery(SortSpec sort, Integer theMaximumResults, boolean theCount) { @@ -2458,6 +2459,7 @@ public class SearchBuilder implements ISearchBuilder { private final class QueryIterator extends BaseIterator implements IResultIterator { + private final SearchRuntimeDetails mySearchRuntimeDetails; private boolean myFirst = true; private IncludesIterator myIncludesIterator; private Long myNext; @@ -2465,10 +2467,10 @@ public class SearchBuilder implements ISearchBuilder { private Iterator 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 @@ -2479,10 +2481,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) { @@ -2491,6 +2489,8 @@ public class SearchBuilder implements ISearchBuilder { final TypedQuery query = createQuery(mySort, myMaxResultsToFetch, false); + mySearchRuntimeDetails.setQueryStopwatch(new StopWatch()); + Query hibernateQuery = (Query) query; hibernateQuery.setFetchSize(myFetchSize); ScrollableResults scroll = hibernateQuery.scroll(ScrollMode.FORWARD_ONLY); @@ -2518,13 +2518,14 @@ 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; } else { mySkipCount++; } + } } } @@ -2552,13 +2553,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); } } diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/interceptor/PerformanceTracingLoggingInterceptor.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/interceptor/PerformanceTracingLoggingInterceptor.java new file mode 100644 index 00000000000..3711a2c5a36 --- /dev/null +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/interceptor/PerformanceTracingLoggingInterceptor.java @@ -0,0 +1,46 @@ +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; + +@Interceptor(manualRegistration = true) +public class PerformanceTracingLoggingInterceptor { + private static final Logger ourLog = LoggerFactory.getLogger(PerformanceTracingLoggingInterceptor.class); + private final Logger myLog; + private final LogUtil.Level myLevel; + + /** + * Constructor that logs to this class with a level of INFO + */ + public PerformanceTracingLoggingInterceptor() { + this(ourLog, LogUtil.Level.INFO); + } + + /** + * Constructor that logs to a custom logger and level + */ + public PerformanceTracingLoggingInterceptor(Logger theLog, LogUtil.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()); + } + + private void log(String theMessage, Object... theArgs) { + LogUtil.log(myLog, myLevel, theMessage, theArgs); + } + +} diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java index 92f4c56ddf5..a30745862ec 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.jpa.search; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -26,6 +26,7 @@ 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.SearchRuntimeDetails; import ca.uhn.fhir.jpa.searchparam.SearchParameterMap; import ca.uhn.fhir.model.api.Include; import ca.uhn.fhir.rest.api.CacheControlDirective; @@ -290,6 +291,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 +302,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc { // Load the results synchronously final List pids = new ArrayList<>(); - Iterator resultIter = sb.createQuery(theParams, searchUuid); + Iterator resultIter = sb.createQuery(theParams, searchRuntimeDetails); while (resultIter.hasNext()) { pids.add(resultIter.next()); if (loadSynchronousUpTo != null && pids.size() >= loadSynchronousUpTo) { @@ -468,6 +471,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc { private boolean myAdditionalPrefetchThresholdsRemaining; private List myPreviouslyAddedResourcePids; private Integer myMaxResultsToFetch; + private SearchRuntimeDetails mySearchRuntimeDetails; /** * Constructor @@ -478,6 +482,11 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc { myParams = theParams; myResourceType = theResourceType; myCompletionLatch = new CountDownLatch(1); + mySearchRuntimeDetails = new SearchRuntimeDetails(mySearch.getUuid()); + } + + public SearchRuntimeDetails getSearchRuntimeDetails() { + return mySearchRuntimeDetails; } protected Search getSearch() { @@ -860,7 +869,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); /* diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/BaseJpaR4Test.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/BaseJpaR4Test.java index d2e7d7c9808..f6bf6eced40 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/BaseJpaR4Test.java +++ b/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.registerInterceptor(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 diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImplTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImplTest.java index 11b21318be2..e5ad4b68351 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImplTest.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImplTest.java @@ -146,7 +146,7 @@ public class SearchCoordinatorSvcImplTest { List 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 +167,7 @@ public class SearchCoordinatorSvcImplTest { List 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 +224,7 @@ public class SearchCoordinatorSvcImplTest { List 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 +252,7 @@ public class SearchCoordinatorSvcImplTest { List 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 +296,7 @@ public class SearchCoordinatorSvcImplTest { List 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 +385,7 @@ public class SearchCoordinatorSvcImplTest { params.add("name", new StringParam("ANAME")); List 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 +406,7 @@ public class SearchCoordinatorSvcImplTest { params.add("name", new StringParam("ANAME")); List 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)); diff --git a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/HookParams.java b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/HookParams.java index 11ec5e61beb..fee4ba6b206 100644 --- a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/HookParams.java +++ b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/HookParams.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.jpa.model.interceptor.api; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -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,41 @@ public class HookParams { } public HookParams add(Class theType, T theParam) { + return doAdd(theType, theParam); + } + + /** + * This is useful for providing a lazy-loaded (generally expensive to create) + * parameters + */ + public HookParams addSupplier(Class theType, Supplier theParam) { + return doAdd(theType, theParam); + } + + private HookParams doAdd(Class theType, Object theParam) { + Validate.isTrue(theType.equals(Supplier.class) == false, "Can not add parameters of type Supplier"); myParams.put(theType, theParam); return this; } @SuppressWarnings("unchecked") public T get(Class theParamType, int theIndex) { - List objects = (List) myParams.get(theParamType); - T retVal = null; + List objects = myParams.get(theParamType); + 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 +99,16 @@ public class HookParams { * key is the param type and the value is the actual instance */ public ListMultimap, Object> getParamsForType() { - return Multimaps.unmodifiableListMultimap(myParams); + ArrayListMultimap, Object> retVal = ArrayListMultimap.create(); + myParams.entries().forEach(entry -> retVal.put(entry.getKey(), unwrapValue(entry.getValue()))); + return Multimaps.unmodifiableListMultimap(retVal); } public Collection values() { - return Collections.unmodifiableCollection(myParams.values()); + return + Collections.unmodifiableCollection(myParams.values()) + .stream() + .map(t -> unwrapValue(t)) + .collect(Collectors.toList()); } } diff --git a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/IInterceptorRegistry.java b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/IInterceptorRegistry.java index af5a9258911..2c0eeb1f65d 100644 --- a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/IInterceptorRegistry.java +++ b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/IInterceptorRegistry.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.jpa.model.interceptor.api; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -26,6 +26,30 @@ 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. + *

+ * 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. + *

+ * + * @param theInterceptor The interceptor + * @return Returns true 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. * diff --git a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/Pointcut.java b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/Pointcut.java index 29854a5fa05..74025e7f711 100644 --- a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/Pointcut.java +++ b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/api/Pointcut.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.jpa.model.interceptor.api; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -20,6 +20,8 @@ package ca.uhn.fhir.jpa.model.interceptor.api; * #L% */ +import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails; + import java.util.Arrays; import java.util.Collections; import java.util.List; @@ -360,7 +362,51 @@ public enum Pointcut { * Hooks should return void. *

*/ - 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. + *

+ * 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. + *

+ * Hooks may accept the following parameters: + *
    + *
  • + * ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails - Contains details about the search being + * performed. Hooks should not modify this object. + *
  • + *
+ *

+ * Hooks should return void. + *

+ */ + 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. + *

+ * 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. + *

+ * Hooks may accept the following parameters: + *
    + *
  • + * ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails - Contains details about the search being + * performed. Hooks should not modify this object. + *
  • + *
+ *

+ * Hooks should return void. + *

+ */ + PERFTRACE_SEARCH_SELECT_COMPLETE(SearchRuntimeDetails.class.getName()); private final List myParameterTypes; diff --git a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorService.java b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorService.java index 0df3ef841de..bfb1e6db0dc 100644 --- a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorService.java +++ b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorService.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.jpa.model.interceptor.executor; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -25,11 +25,9 @@ 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 org.springframework.stereotype.Component; @@ -43,11 +41,12 @@ import java.util.stream.Collectors; @Component public class InterceptorService implements IInterceptorRegistry, IInterceptorBroadcaster { - private static final Logger ourLog = LoggerFactory.getLogger(InterceptorService.class); private final List myInterceptors = new ArrayList<>(); - private final ListMultimap myInvokers = ArrayListMultimap.create(); + private final ListMultimap myGlobalInvokers = ArrayListMultimap.create(); private final ListMultimap myAnonymousInvokers = ArrayListMultimap.create(); private final Object myRegistryMutex = new Object(); + private final ThreadLocal> myThreadlocalInvokers = new ThreadLocal<>(); + private boolean myThreadlocalInvokersEnabled; /** * Constructor @@ -56,6 +55,14 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro super(); } + public boolean isThreadlocalInvokersEnabled() { + return myThreadlocalInvokersEnabled; + } + + public void setThreadlocalInvokersEnabled(boolean theThreadlocalInvokersEnabled) { + myThreadlocalInvokersEnabled = theThreadlocalInvokersEnabled; + } + @VisibleForTesting List getGlobalInterceptorsForUnitTest() { return myInterceptors; @@ -82,6 +89,37 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro myAnonymousInvokers.clear(); } + @Override + public boolean registerThreadLocalInterceptor(Object theInterceptor) { + if (!myThreadlocalInvokersEnabled) { + return false; + } + ListMultimap invokers = getThreadLocalInvokerMultimap(); + scanInterceptorAndAddToInvokerMultimap(theInterceptor, invokers); + return !invokers.isEmpty(); + + } + + @Override + public void unregisterThreadLocalInterceptor(Object theInterceptor) { + if (myThreadlocalInvokersEnabled) { + ListMultimap invokers = getThreadLocalInvokerMultimap(); + invokers.entries().removeIf(t -> t.getValue().getInterceptor() == theInterceptor); + if (invokers.isEmpty()) { + myThreadlocalInvokers.remove(); + } + } + } + + private ListMultimap getThreadLocalInvokerMultimap() { + ListMultimap invokers = myThreadlocalInvokers.get(); + if (invokers == null) { + invokers = Multimaps.synchronizedListMultimap(ArrayListMultimap.create()); + myThreadlocalInvokers.set(invokers); + } + return invokers; + } + @Override public boolean registerInterceptor(Object theInterceptor) { synchronized (myRegistryMutex) { @@ -90,73 +128,19 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro return false; } - Class interceptorClass = theInterceptor.getClass(); - int typeOrder = determineOrder(interceptorClass); - - List addedInvokers = scanInterceptorForHookMethods(theInterceptor, typeOrder); + List addedInvokers = scanInterceptorAndAddToInvokerMultimap(theInterceptor, myGlobalInvokers); if (addedInvokers.isEmpty()) { return false; } - // 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 + // Add to the global list 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 nextInvokerList = myInvokers.get(nextPointcut); - nextInvokerList.sort(Comparator.naturalOrder()); - } return true; } } - /** - * @return Returns a list of any added invokers - */ - private List scanInterceptorForHookMethods(Object theInterceptor, int theTypeOrder) { - ArrayList 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) { @@ -170,7 +154,7 @@ 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); } } @@ -237,20 +221,72 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro */ private List getInvokersForPointcut(Pointcut thePointcut) { List invokers; - boolean haveAnonymousInvokers; + synchronized (myRegistryMutex) { - List globalInvokers = myInvokers.get(thePointcut); + List globalInvokers = myGlobalInvokers.get(thePointcut); List anonymousInvokers = myAnonymousInvokers.get(thePointcut); - invokers = ListUtils.union(anonymousInvokers, globalInvokers); - haveAnonymousInvokers = anonymousInvokers.isEmpty() == false; + List threadLocalInvokers = null; + if (myThreadlocalInvokersEnabled) { + ListMultimap 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 union(List... theInvokersLists) { + List haveOne = null; + boolean haveMultiple = false; + for (List nextInvokerList : theInvokersLists) { + if (nextInvokerList == null || nextInvokerList.isEmpty()) { + continue; + } + + if (haveOne == null) { + haveOne = nextInvokerList; + } else { + haveMultiple = true; + } + } + + if (haveOne == null) { + return Collections.emptyList(); + } + + List 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 */ @@ -271,7 +307,22 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro return true; } - private abstract class BaseInvoker implements Comparable { + private class AnonymousLambdaInvoker 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 abstract static class BaseInvoker implements Comparable { private final int myOrder; private final Object myInterceptor; @@ -288,27 +339,12 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro abstract boolean invoke(HookParams theParams); @Override - public int compareTo(BaseInvoker o) { - return myOrder - o.myOrder; + public int compareTo(BaseInvoker theInvoker) { + return myOrder - theInvoker.myOrder; } } - private class AnonymousLambdaInvoker 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 static class HookInvoker extends BaseInvoker { private final boolean myReturnsBoolean; private final Method myMethod; @@ -382,6 +418,68 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro } + private static List scanInterceptorAndAddToInvokerMultimap(Object theInterceptor, ListMultimap theInvokers) { + Class interceptorClass = theInterceptor.getClass(); + int typeOrder = determineOrder(interceptorClass); + + List 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 nextInvokerList = theInvokers.get(nextPointcut); + nextInvokerList.sort(Comparator.naturalOrder()); + } + + return addedInvokers; + } + + /** + * @return Returns a list of any added invokers + */ + private static List scanInterceptorForHookMethods(Object theInterceptor, int theTypeOrder) { + ArrayList 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 theParameterTypes) { return theParameterTypes .stream() diff --git a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/IndexNonDeletedInterceptor.java b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/IndexNonDeletedInterceptor.java index 65a9d640110..55fce538422 100644 --- a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/IndexNonDeletedInterceptor.java +++ b/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 { diff --git a/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/SearchRuntimeDetails.java b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/SearchRuntimeDetails.java new file mode 100644 index 00000000000..506817d93a8 --- /dev/null +++ b/hapi-fhir-jpaserver-model/src/main/java/ca/uhn/fhir/jpa/model/search/SearchRuntimeDetails.java @@ -0,0 +1,46 @@ +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; + + 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; + } +} diff --git a/hapi-fhir-jpaserver-model/src/test/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorServiceTest.java b/hapi-fhir-jpaserver-model/src/test/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorServiceTest.java index d7878b0582d..39e60370139 100644 --- a/hapi-fhir-jpaserver-model/src/test/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorServiceTest.java +++ b/hapi-fhir-jpaserver-model/src/test/java/ca/uhn/fhir/jpa/model/interceptor/executor/InterceptorServiceTest.java @@ -2,11 +2,16 @@ package ca.uhn.fhir.jpa.model.interceptor.executor; import ca.uhn.fhir.jpa.model.interceptor.api.*; 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; @@ -25,15 +30,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 ourInvocations = new ArrayList<>(); private static IBaseResource ourLastResourceOne; private static IBaseResource ourLastResourceTwoA; private static IBaseResource ourLastResourceTwoB; - @Autowired private InterceptorService myInterceptorRegistry; - @Autowired private MyTestInterceptorOne myInterceptorOne; @Autowired @@ -112,6 +116,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 +206,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); + + } + + /** + *
+	 * 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
+	 * 
+ */ + @Test + @Ignore + 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,6 +322,11 @@ 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 { diff --git a/src/changes/changes.xml b/src/changes/changes.xml index 34393052024..723a108d8b8 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -100,6 +100,9 @@ a REFERENCE search parameter was used with arguments that consisted of unqualified resource IDs. + + A non-threadsafe use of DateFormat was cleaned up in the StopWatch class. +