Create a performance interceptor framework for HAPI FHIR
This commit is contained in:
parent
d1667487c2
commit
c701de2861
|
@ -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
|
||||||
|
}
|
||||||
|
|
||||||
|
}
|
|
@ -7,7 +7,6 @@ import java.text.DecimalFormat;
|
||||||
import java.text.NumberFormat;
|
import java.text.NumberFormat;
|
||||||
import java.util.Date;
|
import java.util.Date;
|
||||||
import java.util.LinkedList;
|
import java.util.LinkedList;
|
||||||
import java.util.List;
|
|
||||||
import java.util.concurrent.TimeUnit;
|
import java.util.concurrent.TimeUnit;
|
||||||
|
|
||||||
import static org.apache.commons.lang3.StringUtils.isNotBlank;
|
import static org.apache.commons.lang3.StringUtils.isNotBlank;
|
||||||
|
@ -45,20 +44,16 @@ import static org.apache.commons.lang3.StringUtils.isNotBlank;
|
||||||
*/
|
*/
|
||||||
public class StopWatch {
|
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 static Long ourNowForUnitTest;
|
||||||
private long myStarted = now();
|
private long myStarted = now();
|
||||||
private TaskTiming myCurrentTask;
|
private TaskTiming myCurrentTask;
|
||||||
private LinkedList<TaskTiming> myTasks;
|
private LinkedList<TaskTiming> myTasks;
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Constructor
|
* Constructor
|
||||||
*/
|
*/
|
||||||
public StopWatch() {
|
public StopWatch() {
|
||||||
super();
|
super();
|
||||||
}
|
}
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Constructor
|
* 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)}
|
* Returns a string providing the durations of all tasks collected by {@link #startTask(String)}
|
||||||
*/
|
*/
|
||||||
|
@ -261,77 +269,6 @@ public class StopWatch {
|
||||||
return formatMillis(getMillis());
|
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 static class TaskTiming {
|
||||||
private long myStart;
|
private long myStart;
|
||||||
private long myEnd;
|
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;
|
||||||
|
}
|
||||||
|
|
||||||
}
|
}
|
||||||
|
|
|
@ -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);
|
||||||
|
}
|
||||||
|
|
||||||
|
}
|
|
@ -99,6 +99,7 @@ public class StopWatchTest {
|
||||||
|
|
||||||
@Test
|
@Test
|
||||||
public void testFormatMillis() {
|
public void testFormatMillis() {
|
||||||
|
assertEquals("0.134ms", StopWatch.formatMillis(0.1339d));
|
||||||
assertEquals("1000ms", StopWatch.formatMillis(DateUtils.MILLIS_PER_SECOND));
|
assertEquals("1000ms", StopWatch.formatMillis(DateUtils.MILLIS_PER_SECOND));
|
||||||
assertEquals("00:01:00.000", StopWatch.formatMillis(DateUtils.MILLIS_PER_MINUTE));
|
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));
|
assertEquals("00:01:01", StopWatch.formatMillis(DateUtils.MILLIS_PER_MINUTE + DateUtils.MILLIS_PER_SECOND));
|
||||||
|
|
|
@ -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.entity.*;
|
||||||
import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
|
import ca.uhn.fhir.jpa.model.interceptor.api.HookParams;
|
||||||
import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
|
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.DatabaseBackedPagingProvider;
|
||||||
import ca.uhn.fhir.jpa.search.PersistedJpaBundleProvider;
|
import ca.uhn.fhir.jpa.search.PersistedJpaBundleProvider;
|
||||||
import ca.uhn.fhir.jpa.search.reindex.IResourceReindexingSvc;
|
import ca.uhn.fhir.jpa.search.reindex.IResourceReindexingSvc;
|
||||||
|
@ -1131,7 +1132,9 @@ public abstract class BaseHapiFhirResourceDao<T extends IBaseResource> extends B
|
||||||
HashSet<Long> retVal = new HashSet<Long>();
|
HashSet<Long> retVal = new HashSet<Long>();
|
||||||
|
|
||||||
String uuid = UUID.randomUUID().toString();
|
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()) {
|
while (iter.hasNext()) {
|
||||||
retVal.add(iter.next());
|
retVal.add(iter.next());
|
||||||
}
|
}
|
||||||
|
|
|
@ -21,6 +21,7 @@ package ca.uhn.fhir.jpa.dao;
|
||||||
*/
|
*/
|
||||||
|
|
||||||
import ca.uhn.fhir.context.FhirContext;
|
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.jpa.searchparam.SearchParameterMap;
|
||||||
import ca.uhn.fhir.model.api.Include;
|
import ca.uhn.fhir.model.api.Include;
|
||||||
import ca.uhn.fhir.rest.param.DateRangeParam;
|
import ca.uhn.fhir.rest.param.DateRangeParam;
|
||||||
|
@ -34,7 +35,7 @@ import java.util.Set;
|
||||||
|
|
||||||
public interface ISearchBuilder {
|
public interface ISearchBuilder {
|
||||||
|
|
||||||
IResultIterator createQuery(SearchParameterMap theParams, String theSearchUuid);
|
IResultIterator createQuery(SearchParameterMap theParams, SearchRuntimeDetails theSearchRuntime);
|
||||||
|
|
||||||
void setMaxResultsToFetch(Integer theMaxResultsToFetch);
|
void setMaxResultsToFetch(Integer theMaxResultsToFetch);
|
||||||
|
|
||||||
|
|
|
@ -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.HookParams;
|
||||||
import ca.uhn.fhir.jpa.model.interceptor.api.IInterceptorBroadcaster;
|
import ca.uhn.fhir.jpa.model.interceptor.api.IInterceptorBroadcaster;
|
||||||
import ca.uhn.fhir.jpa.model.interceptor.api.Pointcut;
|
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.model.util.StringNormalizer;
|
||||||
import ca.uhn.fhir.jpa.searchparam.JpaRuntimeSearchParam;
|
import ca.uhn.fhir.jpa.searchparam.JpaRuntimeSearchParam;
|
||||||
import ca.uhn.fhir.jpa.searchparam.MatchUrlService;
|
import ca.uhn.fhir.jpa.searchparam.MatchUrlService;
|
||||||
|
@ -117,6 +118,8 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
private final boolean myDontUseHashesForSearch;
|
private final boolean myDontUseHashesForSearch;
|
||||||
private final DaoConfig myDaoConfig;
|
private final DaoConfig myDaoConfig;
|
||||||
@Autowired
|
@Autowired
|
||||||
|
protected IInterceptorBroadcaster myInterceptorBroadcaster;
|
||||||
|
@Autowired
|
||||||
protected IResourceTagDao myResourceTagDao;
|
protected IResourceTagDao myResourceTagDao;
|
||||||
@PersistenceContext(type = PersistenceContextType.TRANSACTION)
|
@PersistenceContext(type = PersistenceContextType.TRANSACTION)
|
||||||
protected EntityManager myEntityManager;
|
protected EntityManager myEntityManager;
|
||||||
|
@ -140,8 +143,6 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
private MatchUrlService myMatchUrlService;
|
private MatchUrlService myMatchUrlService;
|
||||||
@Autowired
|
@Autowired
|
||||||
private IResourceIndexedCompositeStringUniqueDao myResourceIndexedCompositeStringUniqueDao;
|
private IResourceIndexedCompositeStringUniqueDao myResourceIndexedCompositeStringUniqueDao;
|
||||||
@Autowired
|
|
||||||
private IInterceptorBroadcaster myInterceptorBroadcaster;
|
|
||||||
private List<Long> myAlsoIncludePids;
|
private List<Long> myAlsoIncludePids;
|
||||||
private CriteriaBuilder myBuilder;
|
private CriteriaBuilder myBuilder;
|
||||||
private BaseHapiFhirDao<?> myCallingDao;
|
private BaseHapiFhirDao<?> myCallingDao;
|
||||||
|
@ -1524,10 +1525,10 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
}
|
}
|
||||||
|
|
||||||
@Override
|
@Override
|
||||||
public IResultIterator createQuery(SearchParameterMap theParams, String theSearchUuid) {
|
public IResultIterator createQuery(SearchParameterMap theParams, SearchRuntimeDetails theSearchRuntimeDetails) {
|
||||||
myParams = theParams;
|
myParams = theParams;
|
||||||
myBuilder = myEntityManager.getCriteriaBuilder();
|
myBuilder = myEntityManager.getCriteriaBuilder();
|
||||||
mySearchUuid = theSearchUuid;
|
mySearchUuid = theSearchRuntimeDetails.getSearchUuid();
|
||||||
|
|
||||||
if (ourTrackHandlersForUnitTest) {
|
if (ourTrackHandlersForUnitTest) {
|
||||||
ourLastHandlerParamsForUnitTest = theParams;
|
ourLastHandlerParamsForUnitTest = theParams;
|
||||||
|
@ -1539,7 +1540,7 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
myPidSet = new HashSet<>();
|
myPidSet = new HashSet<>();
|
||||||
}
|
}
|
||||||
|
|
||||||
return new QueryIterator();
|
return new QueryIterator(theSearchRuntimeDetails);
|
||||||
}
|
}
|
||||||
|
|
||||||
private TypedQuery<Long> createQuery(SortSpec sort, Integer theMaximumResults, boolean theCount) {
|
private TypedQuery<Long> createQuery(SortSpec sort, Integer theMaximumResults, boolean theCount) {
|
||||||
|
@ -2458,6 +2459,7 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
|
|
||||||
private final class QueryIterator extends BaseIterator<Long> implements IResultIterator {
|
private final class QueryIterator extends BaseIterator<Long> implements IResultIterator {
|
||||||
|
|
||||||
|
private final SearchRuntimeDetails mySearchRuntimeDetails;
|
||||||
private boolean myFirst = true;
|
private boolean myFirst = true;
|
||||||
private IncludesIterator myIncludesIterator;
|
private IncludesIterator myIncludesIterator;
|
||||||
private Long myNext;
|
private Long myNext;
|
||||||
|
@ -2465,10 +2467,10 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
private Iterator<Long> myResultsIterator;
|
private Iterator<Long> myResultsIterator;
|
||||||
private SortSpec mySort;
|
private SortSpec mySort;
|
||||||
private boolean myStillNeedToFetchIncludes;
|
private boolean myStillNeedToFetchIncludes;
|
||||||
private StopWatch myStopwatch = null;
|
|
||||||
private int mySkipCount = 0;
|
private int mySkipCount = 0;
|
||||||
|
|
||||||
private QueryIterator() {
|
private QueryIterator(SearchRuntimeDetails theSearchRuntimeDetails) {
|
||||||
|
mySearchRuntimeDetails = theSearchRuntimeDetails;
|
||||||
mySort = myParams.getSort();
|
mySort = myParams.getSort();
|
||||||
|
|
||||||
// Includes are processed inline for $everything query
|
// Includes are processed inline for $everything query
|
||||||
|
@ -2479,10 +2481,6 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
|
|
||||||
private void fetchNext() {
|
private void fetchNext() {
|
||||||
|
|
||||||
if (myFirst) {
|
|
||||||
myStopwatch = new StopWatch();
|
|
||||||
}
|
|
||||||
|
|
||||||
// If we don't have a query yet, create one
|
// If we don't have a query yet, create one
|
||||||
if (myResultsIterator == null) {
|
if (myResultsIterator == null) {
|
||||||
if (myMaxResultsToFetch == null) {
|
if (myMaxResultsToFetch == null) {
|
||||||
|
@ -2491,6 +2489,8 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
|
|
||||||
final TypedQuery<Long> query = createQuery(mySort, myMaxResultsToFetch, false);
|
final TypedQuery<Long> query = createQuery(mySort, myMaxResultsToFetch, false);
|
||||||
|
|
||||||
|
mySearchRuntimeDetails.setQueryStopwatch(new StopWatch());
|
||||||
|
|
||||||
Query<Long> hibernateQuery = (Query<Long>) query;
|
Query<Long> hibernateQuery = (Query<Long>) query;
|
||||||
hibernateQuery.setFetchSize(myFetchSize);
|
hibernateQuery.setFetchSize(myFetchSize);
|
||||||
ScrollableResults scroll = hibernateQuery.scroll(ScrollMode.FORWARD_ONLY);
|
ScrollableResults scroll = hibernateQuery.scroll(ScrollMode.FORWARD_ONLY);
|
||||||
|
@ -2518,7 +2518,7 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
if (myNext == null) {
|
if (myNext == null) {
|
||||||
while (myResultsIterator.hasNext()) {
|
while (myResultsIterator.hasNext()) {
|
||||||
Long next = myResultsIterator.next();
|
Long next = myResultsIterator.next();
|
||||||
if (next != null)
|
if (next != null) {
|
||||||
if (myPidSet.add(next)) {
|
if (myPidSet.add(next)) {
|
||||||
myNext = next;
|
myNext = next;
|
||||||
break;
|
break;
|
||||||
|
@ -2527,6 +2527,7 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
}
|
||||||
|
|
||||||
if (myNext == null) {
|
if (myNext == null) {
|
||||||
if (myStillNeedToFetchIncludes) {
|
if (myStillNeedToFetchIncludes) {
|
||||||
|
@ -2552,13 +2553,15 @@ public class SearchBuilder implements ISearchBuilder {
|
||||||
|
|
||||||
} // if we need to fetch the next result
|
} // if we need to fetch the next result
|
||||||
|
|
||||||
|
mySearchRuntimeDetails.setFoundMatchesCount(myPidSet.size());
|
||||||
|
|
||||||
if (myFirst) {
|
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;
|
myFirst = false;
|
||||||
}
|
}
|
||||||
|
|
||||||
if (NO_MORE.equals(myNext)) {
|
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);
|
||||||
}
|
}
|
||||||
|
|
||||||
}
|
}
|
||||||
|
|
|
@ -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);
|
||||||
|
}
|
||||||
|
|
||||||
|
}
|
|
@ -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.ISearchIncludeDao;
|
||||||
import ca.uhn.fhir.jpa.dao.data.ISearchResultDao;
|
import ca.uhn.fhir.jpa.dao.data.ISearchResultDao;
|
||||||
import ca.uhn.fhir.jpa.entity.*;
|
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.jpa.searchparam.SearchParameterMap;
|
||||||
import ca.uhn.fhir.model.api.Include;
|
import ca.uhn.fhir.model.api.Include;
|
||||||
import ca.uhn.fhir.rest.api.CacheControlDirective;
|
import ca.uhn.fhir.rest.api.CacheControlDirective;
|
||||||
|
@ -290,6 +291,8 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
|
||||||
if (theParams.isLoadSynchronous() || loadSynchronousUpTo != null) {
|
if (theParams.isLoadSynchronous() || loadSynchronousUpTo != null) {
|
||||||
|
|
||||||
ourLog.debug("Search {} is loading in synchronous mode", searchUuid);
|
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
|
// Execute the query and make sure we return distinct results
|
||||||
TransactionTemplate txTemplate = new TransactionTemplate(myManagedTxManager);
|
TransactionTemplate txTemplate = new TransactionTemplate(myManagedTxManager);
|
||||||
|
@ -299,7 +302,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
|
||||||
// Load the results synchronously
|
// Load the results synchronously
|
||||||
final List<Long> pids = new ArrayList<>();
|
final List<Long> pids = new ArrayList<>();
|
||||||
|
|
||||||
Iterator<Long> resultIter = sb.createQuery(theParams, searchUuid);
|
Iterator<Long> resultIter = sb.createQuery(theParams, searchRuntimeDetails);
|
||||||
while (resultIter.hasNext()) {
|
while (resultIter.hasNext()) {
|
||||||
pids.add(resultIter.next());
|
pids.add(resultIter.next());
|
||||||
if (loadSynchronousUpTo != null && pids.size() >= loadSynchronousUpTo) {
|
if (loadSynchronousUpTo != null && pids.size() >= loadSynchronousUpTo) {
|
||||||
|
@ -468,6 +471,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
|
||||||
private boolean myAdditionalPrefetchThresholdsRemaining;
|
private boolean myAdditionalPrefetchThresholdsRemaining;
|
||||||
private List<Long> myPreviouslyAddedResourcePids;
|
private List<Long> myPreviouslyAddedResourcePids;
|
||||||
private Integer myMaxResultsToFetch;
|
private Integer myMaxResultsToFetch;
|
||||||
|
private SearchRuntimeDetails mySearchRuntimeDetails;
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Constructor
|
* Constructor
|
||||||
|
@ -478,6 +482,11 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
|
||||||
myParams = theParams;
|
myParams = theParams;
|
||||||
myResourceType = theResourceType;
|
myResourceType = theResourceType;
|
||||||
myCompletionLatch = new CountDownLatch(1);
|
myCompletionLatch = new CountDownLatch(1);
|
||||||
|
mySearchRuntimeDetails = new SearchRuntimeDetails(mySearch.getUuid());
|
||||||
|
}
|
||||||
|
|
||||||
|
public SearchRuntimeDetails getSearchRuntimeDetails() {
|
||||||
|
return mySearchRuntimeDetails;
|
||||||
}
|
}
|
||||||
|
|
||||||
protected Search getSearch() {
|
protected Search getSearch() {
|
||||||
|
@ -860,7 +869,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
|
||||||
/*
|
/*
|
||||||
* Construct the SQL query we'll be sending to the database
|
* 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);
|
assert (resultIterator != null);
|
||||||
|
|
||||||
/*
|
/*
|
||||||
|
|
|
@ -5,6 +5,7 @@ import ca.uhn.fhir.jpa.config.TestR4Config;
|
||||||
import ca.uhn.fhir.jpa.dao.*;
|
import ca.uhn.fhir.jpa.dao.*;
|
||||||
import ca.uhn.fhir.jpa.dao.data.*;
|
import ca.uhn.fhir.jpa.dao.data.*;
|
||||||
import ca.uhn.fhir.jpa.dao.dstu2.FhirResourceDaoDstu2SearchNoFtTest;
|
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.ModelConfig;
|
||||||
import ca.uhn.fhir.jpa.model.entity.ResourceIndexedSearchParamString;
|
import ca.uhn.fhir.jpa.model.entity.ResourceIndexedSearchParamString;
|
||||||
import ca.uhn.fhir.jpa.model.entity.ResourceTable;
|
import ca.uhn.fhir.jpa.model.entity.ResourceTable;
|
||||||
|
@ -286,6 +287,8 @@ public abstract class BaseJpaR4Test extends BaseJpaTest {
|
||||||
@Autowired
|
@Autowired
|
||||||
protected SubscriptionRegistry mySubscriptionRegistry;
|
protected SubscriptionRegistry mySubscriptionRegistry;
|
||||||
|
|
||||||
|
private PerformanceTracingLoggingInterceptor myPerformanceTracingLoggingInterceptor;
|
||||||
|
|
||||||
@After()
|
@After()
|
||||||
public void afterCleanupDao() {
|
public void afterCleanupDao() {
|
||||||
myDaoConfig.setExpireSearchResults(new DaoConfig().isExpireSearchResults());
|
myDaoConfig.setExpireSearchResults(new DaoConfig().isExpireSearchResults());
|
||||||
|
@ -318,6 +321,9 @@ public abstract class BaseJpaR4Test extends BaseJpaTest {
|
||||||
public void beforeCreateInterceptor() {
|
public void beforeCreateInterceptor() {
|
||||||
myInterceptor = mock(IServerInterceptor.class);
|
myInterceptor = mock(IServerInterceptor.class);
|
||||||
myDaoConfig.setInterceptors(myInterceptor);
|
myDaoConfig.setInterceptors(myInterceptor);
|
||||||
|
|
||||||
|
myPerformanceTracingLoggingInterceptor = new PerformanceTracingLoggingInterceptor();
|
||||||
|
myInterceptorRegistry.registerInterceptor(myPerformanceTracingLoggingInterceptor);
|
||||||
}
|
}
|
||||||
|
|
||||||
@Before
|
@Before
|
||||||
|
@ -345,6 +351,8 @@ public abstract class BaseJpaR4Test extends BaseJpaTest {
|
||||||
myDaoConfig.setHardTagListLimit(1000);
|
myDaoConfig.setHardTagListLimit(1000);
|
||||||
myDaoConfig.setIncludeLimit(2000);
|
myDaoConfig.setIncludeLimit(2000);
|
||||||
myFhirCtx.setParserErrorHandler(new StrictErrorHandler());
|
myFhirCtx.setParserErrorHandler(new StrictErrorHandler());
|
||||||
|
|
||||||
|
myInterceptorRegistry.unregisterInterceptor(myPerformanceTracingLoggingInterceptor);
|
||||||
}
|
}
|
||||||
|
|
||||||
@Override
|
@Override
|
||||||
|
|
|
@ -146,7 +146,7 @@ public class SearchCoordinatorSvcImplTest {
|
||||||
|
|
||||||
List<Long> pids = createPidSequence(10, 800);
|
List<Long> pids = createPidSequence(10, 800);
|
||||||
IResultIterator iter = new FailAfterNIterator(new SlowIterator(pids.iterator(), 2), 300);
|
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());
|
IBundleProvider result = mySvc.registerSearch(myCallingDao, params, "Patient", new CacheControlDirective());
|
||||||
assertNotNull(result.getUuid());
|
assertNotNull(result.getUuid());
|
||||||
|
@ -167,7 +167,7 @@ public class SearchCoordinatorSvcImplTest {
|
||||||
|
|
||||||
List<Long> pids = createPidSequence(10, 800);
|
List<Long> pids = createPidSequence(10, 800);
|
||||||
SlowIterator iter = new SlowIterator(pids.iterator(), 1);
|
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));
|
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 -> {
|
when(mySearchResultDao.findWithSearchUuid(any(), any())).thenAnswer(t -> {
|
||||||
|
@ -224,7 +224,7 @@ public class SearchCoordinatorSvcImplTest {
|
||||||
|
|
||||||
List<Long> pids = createPidSequence(10, 800);
|
List<Long> pids = createPidSequence(10, 800);
|
||||||
SlowIterator iter = new SlowIterator(pids.iterator(), 2);
|
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));
|
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<Long> pids = createPidSequence(10, 800);
|
List<Long> pids = createPidSequence(10, 800);
|
||||||
IResultIterator iter = new SlowIterator(pids.iterator(), 2);
|
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]);
|
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));
|
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<Long> pids = createPidSequence(10, 100);
|
List<Long> pids = createPidSequence(10, 100);
|
||||||
SlowIterator iter = new SlowIterator(pids.iterator(), 2);
|
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));
|
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"));
|
params.add("name", new StringParam("ANAME"));
|
||||||
|
|
||||||
List<Long> pids = createPidSequence(10, 800);
|
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));
|
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"));
|
params.add("name", new StringParam("ANAME"));
|
||||||
|
|
||||||
List<Long> pids = createPidSequence(10, 800);
|
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);
|
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));
|
doAnswer(loadPids()).when(mySearchBuider).loadResourcesByPid(eq(pids), any(List.class), any(Set.class), anyBoolean(), any(EntityManager.class), any(FhirContext.class), same(myCallingDao));
|
||||||
|
|
|
@ -23,10 +23,13 @@ package ca.uhn.fhir.jpa.model.interceptor.api;
|
||||||
import com.google.common.collect.ArrayListMultimap;
|
import com.google.common.collect.ArrayListMultimap;
|
||||||
import com.google.common.collect.ListMultimap;
|
import com.google.common.collect.ListMultimap;
|
||||||
import com.google.common.collect.Multimaps;
|
import com.google.common.collect.Multimaps;
|
||||||
|
import org.apache.commons.lang3.Validate;
|
||||||
|
|
||||||
import java.util.Collection;
|
import java.util.Collection;
|
||||||
import java.util.Collections;
|
import java.util.Collections;
|
||||||
import java.util.List;
|
import java.util.List;
|
||||||
|
import java.util.function.Supplier;
|
||||||
|
import java.util.stream.Collectors;
|
||||||
|
|
||||||
public class HookParams {
|
public class HookParams {
|
||||||
|
|
||||||
|
@ -54,18 +57,41 @@ public class HookParams {
|
||||||
}
|
}
|
||||||
|
|
||||||
public <T> HookParams add(Class<T> theType, T theParam) {
|
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);
|
myParams.put(theType, theParam);
|
||||||
return this;
|
return this;
|
||||||
}
|
}
|
||||||
|
|
||||||
@SuppressWarnings("unchecked")
|
@SuppressWarnings("unchecked")
|
||||||
public <T> T get(Class<T> theParamType, int theIndex) {
|
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) {
|
if (objects.size() > theIndex) {
|
||||||
retVal = objects.get(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
|
* key is the param type and the value is the actual instance
|
||||||
*/
|
*/
|
||||||
public ListMultimap<Class<?>, Object> getParamsForType() {
|
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() {
|
public Collection<Object> values() {
|
||||||
return Collections.unmodifiableCollection(myParams.values());
|
return
|
||||||
|
Collections.unmodifiableCollection(myParams.values())
|
||||||
|
.stream()
|
||||||
|
.map(t -> unwrapValue(t))
|
||||||
|
.collect(Collectors.toList());
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
|
@ -26,6 +26,30 @@ public interface IInterceptorRegistry {
|
||||||
|
|
||||||
int DEFAULT_ORDER = 0;
|
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.
|
* Register an interceptor. This method has no effect if the given interceptor is already registered.
|
||||||
*
|
*
|
||||||
|
|
|
@ -20,6 +20,8 @@ package ca.uhn.fhir.jpa.model.interceptor.api;
|
||||||
* #L%
|
* #L%
|
||||||
*/
|
*/
|
||||||
|
|
||||||
|
import ca.uhn.fhir.jpa.model.search.SearchRuntimeDetails;
|
||||||
|
|
||||||
import java.util.Arrays;
|
import java.util.Arrays;
|
||||||
import java.util.Collections;
|
import java.util.Collections;
|
||||||
import java.util.List;
|
import java.util.List;
|
||||||
|
@ -360,7 +362,51 @@ public enum Pointcut {
|
||||||
* Hooks should return <code>void</code>.
|
* Hooks should return <code>void</code>.
|
||||||
* </p>
|
* </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());
|
||||||
|
|
||||||
private final List<String> myParameterTypes;
|
private final List<String> myParameterTypes;
|
||||||
|
|
||||||
|
|
|
@ -25,11 +25,9 @@ import ca.uhn.fhir.rest.server.exceptions.InternalErrorException;
|
||||||
import com.google.common.annotations.VisibleForTesting;
|
import com.google.common.annotations.VisibleForTesting;
|
||||||
import com.google.common.collect.ArrayListMultimap;
|
import com.google.common.collect.ArrayListMultimap;
|
||||||
import com.google.common.collect.ListMultimap;
|
import com.google.common.collect.ListMultimap;
|
||||||
|
import com.google.common.collect.Multimaps;
|
||||||
import com.google.common.collect.Sets;
|
import com.google.common.collect.Sets;
|
||||||
import org.apache.commons.collections4.ListUtils;
|
|
||||||
import org.apache.commons.lang3.Validate;
|
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.AnnotationUtils;
|
||||||
import org.springframework.core.annotation.Order;
|
import org.springframework.core.annotation.Order;
|
||||||
import org.springframework.stereotype.Component;
|
import org.springframework.stereotype.Component;
|
||||||
|
@ -43,11 +41,12 @@ import java.util.stream.Collectors;
|
||||||
|
|
||||||
@Component
|
@Component
|
||||||
public class InterceptorService implements IInterceptorRegistry, IInterceptorBroadcaster {
|
public class InterceptorService implements IInterceptorRegistry, IInterceptorBroadcaster {
|
||||||
private static final Logger ourLog = LoggerFactory.getLogger(InterceptorService.class);
|
|
||||||
private final List<Object> myInterceptors = new ArrayList<>();
|
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 ListMultimap<Pointcut, BaseInvoker> myAnonymousInvokers = ArrayListMultimap.create();
|
||||||
private final Object myRegistryMutex = new Object();
|
private final Object myRegistryMutex = new Object();
|
||||||
|
private final ThreadLocal<ListMultimap<Pointcut, BaseInvoker>> myThreadlocalInvokers = new ThreadLocal<>();
|
||||||
|
private boolean myThreadlocalInvokersEnabled;
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Constructor
|
* Constructor
|
||||||
|
@ -56,6 +55,14 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
|
||||||
super();
|
super();
|
||||||
}
|
}
|
||||||
|
|
||||||
|
public boolean isThreadlocalInvokersEnabled() {
|
||||||
|
return myThreadlocalInvokersEnabled;
|
||||||
|
}
|
||||||
|
|
||||||
|
public void setThreadlocalInvokersEnabled(boolean theThreadlocalInvokersEnabled) {
|
||||||
|
myThreadlocalInvokersEnabled = theThreadlocalInvokersEnabled;
|
||||||
|
}
|
||||||
|
|
||||||
@VisibleForTesting
|
@VisibleForTesting
|
||||||
List<Object> getGlobalInterceptorsForUnitTest() {
|
List<Object> getGlobalInterceptorsForUnitTest() {
|
||||||
return myInterceptors;
|
return myInterceptors;
|
||||||
|
@ -82,6 +89,37 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
|
||||||
myAnonymousInvokers.clear();
|
myAnonymousInvokers.clear();
|
||||||
}
|
}
|
||||||
|
|
||||||
|
@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
|
@Override
|
||||||
public boolean registerInterceptor(Object theInterceptor) {
|
public boolean registerInterceptor(Object theInterceptor) {
|
||||||
synchronized (myRegistryMutex) {
|
synchronized (myRegistryMutex) {
|
||||||
|
@ -90,73 +128,19 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
|
||||||
return false;
|
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()) {
|
if (addedInvokers.isEmpty()) {
|
||||||
return false;
|
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);
|
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);
|
sortByOrderAnnotation(myInterceptors);
|
||||||
for (Pointcut nextPointcut : myInvokers.keys()) {
|
|
||||||
List<BaseInvoker> nextInvokerList = myInvokers.get(nextPointcut);
|
|
||||||
nextInvokerList.sort(Comparator.naturalOrder());
|
|
||||||
}
|
|
||||||
|
|
||||||
return true;
|
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) {
|
private boolean isInterceptorAlreadyRegistered(Object theInterceptor) {
|
||||||
for (Object next : myInterceptors) {
|
for (Object next : myInterceptors) {
|
||||||
if (next == theInterceptor) {
|
if (next == theInterceptor) {
|
||||||
|
@ -170,7 +154,7 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
|
||||||
public void unregisterInterceptor(Object theInterceptor) {
|
public void unregisterInterceptor(Object theInterceptor) {
|
||||||
synchronized (myRegistryMutex) {
|
synchronized (myRegistryMutex) {
|
||||||
myInterceptors.removeIf(t -> t == theInterceptor);
|
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<BaseInvoker> getInvokersForPointcut(Pointcut thePointcut) {
|
private List<BaseInvoker> getInvokersForPointcut(Pointcut thePointcut) {
|
||||||
List<BaseInvoker> invokers;
|
List<BaseInvoker> invokers;
|
||||||
boolean haveAnonymousInvokers;
|
|
||||||
synchronized (myRegistryMutex) {
|
synchronized (myRegistryMutex) {
|
||||||
List<BaseInvoker> globalInvokers = myInvokers.get(thePointcut);
|
List<BaseInvoker> globalInvokers = myGlobalInvokers.get(thePointcut);
|
||||||
List<BaseInvoker> anonymousInvokers = myAnonymousInvokers.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;
|
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
|
* Only call this when assertions are enabled, it's expensive
|
||||||
*/
|
*/
|
||||||
|
@ -271,7 +307,22 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
|
||||||
return true;
|
return true;
|
||||||
}
|
}
|
||||||
|
|
||||||
private abstract class BaseInvoker implements Comparable<BaseInvoker> {
|
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<BaseInvoker> {
|
||||||
|
|
||||||
private final int myOrder;
|
private final int myOrder;
|
||||||
private final Object myInterceptor;
|
private final Object myInterceptor;
|
||||||
|
@ -288,27 +339,12 @@ public class InterceptorService implements IInterceptorRegistry, IInterceptorBro
|
||||||
abstract boolean invoke(HookParams theParams);
|
abstract boolean invoke(HookParams theParams);
|
||||||
|
|
||||||
@Override
|
@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 boolean myReturnsBoolean;
|
||||||
private final Method myMethod;
|
private final Method myMethod;
|
||||||
|
@ -382,6 +418,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) {
|
private static String toErrorString(List<String> theParameterTypes) {
|
||||||
return theParameterTypes
|
return theParameterTypes
|
||||||
.stream()
|
.stream()
|
||||||
|
|
|
@ -25,6 +25,10 @@ import org.hibernate.search.indexes.interceptor.EntityIndexingInterceptor;
|
||||||
import org.hibernate.search.indexes.interceptor.IndexingOverride;
|
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
|
* Only store non-deleted resources
|
||||||
*/
|
*/
|
||||||
public class IndexNonDeletedInterceptor implements EntityIndexingInterceptor<ResourceTable> {
|
public class IndexNonDeletedInterceptor implements EntityIndexingInterceptor<ResourceTable> {
|
||||||
|
|
|
@ -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;
|
||||||
|
}
|
||||||
|
}
|
|
@ -2,11 +2,16 @@ package ca.uhn.fhir.jpa.model.interceptor.executor;
|
||||||
|
|
||||||
import ca.uhn.fhir.jpa.model.interceptor.api.*;
|
import ca.uhn.fhir.jpa.model.interceptor.api.*;
|
||||||
import ca.uhn.fhir.rest.server.exceptions.InternalErrorException;
|
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.instance.model.api.IBaseResource;
|
||||||
import org.hl7.fhir.r4.model.Patient;
|
import org.hl7.fhir.r4.model.Patient;
|
||||||
|
import org.junit.After;
|
||||||
import org.junit.Before;
|
import org.junit.Before;
|
||||||
|
import org.junit.Ignore;
|
||||||
import org.junit.Test;
|
import org.junit.Test;
|
||||||
import org.junit.runner.RunWith;
|
import org.junit.runner.RunWith;
|
||||||
|
import org.slf4j.Logger;
|
||||||
|
import org.slf4j.LoggerFactory;
|
||||||
import org.springframework.beans.factory.annotation.Autowired;
|
import org.springframework.beans.factory.annotation.Autowired;
|
||||||
import org.springframework.context.annotation.Bean;
|
import org.springframework.context.annotation.Bean;
|
||||||
import org.springframework.context.annotation.ComponentScan;
|
import org.springframework.context.annotation.ComponentScan;
|
||||||
|
@ -25,15 +30,14 @@ import static org.junit.Assert.*;
|
||||||
@ContextConfiguration(classes = {InterceptorServiceTest.InterceptorRegistryTestCtxConfig.class})
|
@ContextConfiguration(classes = {InterceptorServiceTest.InterceptorRegistryTestCtxConfig.class})
|
||||||
public class InterceptorServiceTest {
|
public class InterceptorServiceTest {
|
||||||
|
|
||||||
|
private static final Logger ourLog = LoggerFactory.getLogger(InterceptorServiceTest.class);
|
||||||
private static boolean ourNext_beforeRestHookDelivery_Return1;
|
private static boolean ourNext_beforeRestHookDelivery_Return1;
|
||||||
private static List<String> ourInvocations = new ArrayList<>();
|
private static List<String> ourInvocations = new ArrayList<>();
|
||||||
private static IBaseResource ourLastResourceOne;
|
private static IBaseResource ourLastResourceOne;
|
||||||
private static IBaseResource ourLastResourceTwoA;
|
private static IBaseResource ourLastResourceTwoA;
|
||||||
private static IBaseResource ourLastResourceTwoB;
|
private static IBaseResource ourLastResourceTwoB;
|
||||||
|
|
||||||
@Autowired
|
@Autowired
|
||||||
private InterceptorService myInterceptorRegistry;
|
private InterceptorService myInterceptorRegistry;
|
||||||
|
|
||||||
@Autowired
|
@Autowired
|
||||||
private MyTestInterceptorOne myInterceptorOne;
|
private MyTestInterceptorOne myInterceptorOne;
|
||||||
@Autowired
|
@Autowired
|
||||||
|
@ -112,6 +116,20 @@ public class InterceptorServiceTest {
|
||||||
assertSame(patient, ourLastResourceOne);
|
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
|
@Test
|
||||||
public void testInvokeGlobalInterceptorMethods_MethodAbortsProcessing() {
|
public void testInvokeGlobalInterceptorMethods_MethodAbortsProcessing() {
|
||||||
ourNext_beforeRestHookDelivery_Return1 = false;
|
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);
|
||||||
|
|
||||||
|
}
|
||||||
|
|
||||||
|
/**
|
||||||
|
* <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
|
||||||
|
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
|
@Before
|
||||||
public void before() {
|
public void before() {
|
||||||
ourNext_beforeRestHookDelivery_Return1 = true;
|
ourNext_beforeRestHookDelivery_Return1 = true;
|
||||||
|
@ -197,6 +322,11 @@ public class InterceptorServiceTest {
|
||||||
ourInvocations.clear();
|
ourInvocations.clear();
|
||||||
}
|
}
|
||||||
|
|
||||||
|
@After
|
||||||
|
public void after() {
|
||||||
|
myInterceptorRegistry.setThreadlocalInvokersEnabled(new InterceptorService().isThreadlocalInvokersEnabled());
|
||||||
|
}
|
||||||
|
|
||||||
@Configuration
|
@Configuration
|
||||||
@ComponentScan(basePackages = "ca.uhn.fhir.jpa.model")
|
@ComponentScan(basePackages = "ca.uhn.fhir.jpa.model")
|
||||||
static class InterceptorRegistryTestCtxConfig {
|
static class InterceptorRegistryTestCtxConfig {
|
||||||
|
|
|
@ -100,6 +100,9 @@
|
||||||
a REFERENCE search parameter was used with arguments that consisted of
|
a REFERENCE search parameter was used with arguments that consisted of
|
||||||
unqualified resource IDs.
|
unqualified resource IDs.
|
||||||
</action>
|
</action>
|
||||||
|
<action type="fix">
|
||||||
|
A non-threadsafe use of DateFormat was cleaned up in the StopWatch class.
|
||||||
|
</action>
|
||||||
</release>
|
</release>
|
||||||
<release version="3.7.0" date="2019-02-06" description="Gale">
|
<release version="3.7.0" date="2019-02-06" description="Gale">
|
||||||
<action type="add">
|
<action type="add">
|
||||||
|
|
Loading…
Reference in New Issue