Add some logging to searches

This commit is contained in:
James 2017-05-25 08:31:29 -04:00
parent 32de48f392
commit e2b329382a
6 changed files with 43 additions and 19 deletions

View File

@ -928,7 +928,8 @@ public abstract class BaseHapiFhirResourceDao<T extends IBaseResource> extends B
HashSet<Long> retVal = new HashSet<Long>(); HashSet<Long> retVal = new HashSet<Long>();
Iterator<Long> iter = builder.createQuery(theParams); String uuid = UUID.randomUUID().toString();
Iterator<Long> iter = builder.createQuery(theParams, uuid);
while (iter.hasNext()) { while (iter.hasNext()) {
retVal.add(iter.next()); retVal.add(iter.next());
} }

View File

@ -35,7 +35,7 @@ import ca.uhn.fhir.rest.param.DateRangeParam;
public interface ISearchBuilder { public interface ISearchBuilder {
Iterator<Long> createQuery(SearchParameterMap theParams); Iterator<Long> createQuery(SearchParameterMap theParams, String theSearchUuid);
void setType(Class<? extends IBaseResource> theResourceType, String theResourceName); void setType(Class<? extends IBaseResource> theResourceType, String theResourceName);

View File

@ -146,6 +146,7 @@ public class SearchBuilder implements ISearchBuilder {
private Class<? extends IBaseResource> myResourceType; private Class<? extends IBaseResource> myResourceType;
private ISearchParamRegistry mySearchParamRegistry; private ISearchParamRegistry mySearchParamRegistry;
private IHapiTerminologySvc myTerminologySvc; private IHapiTerminologySvc myTerminologySvc;
private String mySearchUuid;
/** /**
* Constructor * Constructor
@ -1260,12 +1261,12 @@ public class SearchBuilder implements ISearchBuilder {
} }
@Override @Override
public Iterator<Long> createQuery(SearchParameterMap theParams) { public Iterator<Long> createQuery(SearchParameterMap theParams, String theSearchUuid) {
myParams = theParams; myParams = theParams;
myBuilder = myEntityManager.getCriteriaBuilder(); myBuilder = myEntityManager.getCriteriaBuilder();
mySearchUuid = theSearchUuid;
return new QueryIterator(); return new QueryIterator();
} }
private List<Long> myAlsoIncludePids; private List<Long> myAlsoIncludePids;
@ -1938,6 +1939,7 @@ public class SearchBuilder implements ISearchBuilder {
private Iterator<Long> myResultsIterator; private Iterator<Long> myResultsIterator;
private SortSpec mySort; private SortSpec mySort;
private Iterator<Long> myPreResultsIterator; private Iterator<Long> myPreResultsIterator;
private boolean myFirst = true;
private QueryIterator() { private QueryIterator() {
mySort = myParams.getSort(); mySort = myParams.getSort();
@ -1945,6 +1947,11 @@ public class SearchBuilder implements ISearchBuilder {
private void fetchNext() { private void fetchNext() {
StopWatch sw = null;
if (myFirst) {
sw = 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) {
final TypedQuery<Long> query = createQuery(mySort); final TypedQuery<Long> query = createQuery(mySort);
@ -1981,6 +1988,15 @@ public class SearchBuilder implements ISearchBuilder {
if (myNext == null) { if (myNext == null) {
myNext = NO_MORE; myNext = NO_MORE;
} }
} // if we need to fetch the next result
if (myFirst) {
ourLog.info("Initial query result returned in {}ms for query {}", sw, mySearchUuid);
myFirst = false;
}
if (myNext == NO_MORE) {
ourLog.info("Query found {} matches in {}ms for query {}", myPidSet.size(), sw, mySearchUuid);
} }
} }

View File

@ -219,6 +219,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
@Override @Override
public IBundleProvider registerSearch(final IDao theCallingDao, SearchParameterMap theParams, String theResourceType) { public IBundleProvider registerSearch(final IDao theCallingDao, SearchParameterMap theParams, String theResourceType) {
StopWatch w = new StopWatch(); StopWatch w = new StopWatch();
String searchUuid = UUID.randomUUID().toString();
Class<? extends IBaseResource> resourceTypeClass = myContext.getResourceDefinition(theResourceType).getImplementingClass(); Class<? extends IBaseResource> resourceTypeClass = myContext.getResourceDefinition(theResourceType).getImplementingClass();
final ISearchBuilder sb = theCallingDao.newSearchBuilder(); final ISearchBuilder sb = theCallingDao.newSearchBuilder();
@ -229,7 +230,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
// Load the results synchronously // Load the results synchronously
final List<Long> pids = new ArrayList<Long>(); final List<Long> pids = new ArrayList<Long>();
Iterator<Long> resultIter = sb.createQuery(theParams); Iterator<Long> resultIter = sb.createQuery(theParams, searchUuid);
while (resultIter.hasNext()) { while (resultIter.hasNext()) {
pids.add(resultIter.next()); pids.add(resultIter.next());
if (theParams.getLoadSynchronousUpTo() != null && pids.size() >= theParams.getLoadSynchronousUpTo()) { if (theParams.getLoadSynchronousUpTo() != null && pids.size() >= theParams.getLoadSynchronousUpTo()) {
@ -310,7 +311,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
} }
Search search = new Search(); Search search = new Search();
search.setUuid(UUID.randomUUID().toString()); search.setUuid(searchUuid);
search.setCreated(new Date()); search.setCreated(new Date());
search.setSearchLastReturned(new Date()); search.setSearchLastReturned(new Date());
search.setTotalCount(null); search.setTotalCount(null);
@ -331,7 +332,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
search.getIncludes().add(new SearchInclude(search, next.getValue(), true, next.isRecurse())); search.getIncludes().add(new SearchInclude(search, next.getValue(), true, next.isRecurse()));
} }
SearchTask task = new SearchTask(search, theCallingDao, theParams, theResourceType); SearchTask task = new SearchTask(search, theCallingDao, theParams, theResourceType, searchUuid);
myIdToSearchTask.put(search.getUuid(), task); myIdToSearchTask.put(search.getUuid(), task);
myExecutor.submit(task); myExecutor.submit(task);
@ -439,13 +440,15 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
private final Search mySearch; private final Search mySearch;
private final ArrayList<Long> mySyncedPids = new ArrayList<Long>(); private final ArrayList<Long> mySyncedPids = new ArrayList<Long>();
private final ArrayList<Long> myUnsyncedPids = new ArrayList<Long>(); private final ArrayList<Long> myUnsyncedPids = new ArrayList<Long>();
private String mySearchUuid;
public SearchTask(Search theSearch, IDao theCallingDao, SearchParameterMap theParams, String theResourceType) { public SearchTask(Search theSearch, IDao theCallingDao, SearchParameterMap theParams, String theResourceType, String theSearchUuid) {
mySearch = theSearch; mySearch = theSearch;
myCallingDao = theCallingDao; myCallingDao = theCallingDao;
myParams = theParams; myParams = theParams;
myResourceType = theResourceType; myResourceType = theResourceType;
myCompletionLatch = new CountDownLatch(1); myCompletionLatch = new CountDownLatch(1);
mySearchUuid = theSearchUuid;
} }
public void awaitInitialSync() { public void awaitInitialSync() {
@ -537,7 +540,7 @@ public class SearchCoordinatorSvcImpl implements ISearchCoordinatorSvc {
Class<? extends IBaseResource> resourceTypeClass = myContext.getResourceDefinition(myResourceType).getImplementingClass(); Class<? extends IBaseResource> resourceTypeClass = myContext.getResourceDefinition(myResourceType).getImplementingClass();
ISearchBuilder sb = myCallingDao.newSearchBuilder(); ISearchBuilder sb = myCallingDao.newSearchBuilder();
sb.setType(resourceTypeClass, myResourceType); sb.setType(resourceTypeClass, myResourceType);
Iterator<Long> theResultIter = sb.createQuery(myParams); Iterator<Long> theResultIter = sb.createQuery(myParams, mySearchUuid);
while (theResultIter.hasNext()) { while (theResultIter.hasNext()) {
myUnsyncedPids.add(theResultIter.next()); myUnsyncedPids.add(theResultIter.next());

View File

@ -149,7 +149,7 @@ public class SearchCoordinatorSvcImplTest {
List<Long> pids = createPidSequence(10, 800); List<Long> pids = createPidSequence(10, 800);
Iterator<Long> iter = new FailAfterNIterator<Long>(new SlowIterator<Long>(pids.iterator(), 2), 300); Iterator<Long> iter = new FailAfterNIterator<Long>(new SlowIterator<Long>(pids.iterator(), 2), 300);
when(mySearchBuider.createQuery(Mockito.same(params))).thenReturn(iter); when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).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));
@ -165,6 +165,9 @@ public class SearchCoordinatorSvcImplTest {
} }
private String newUuid() {
return UUID.randomUUID().toString();
}
@Test @Test
public void testAsyncSearchLargeResultSetBigCountSameCoordinator() { public void testAsyncSearchLargeResultSetBigCountSameCoordinator() {
SearchParameterMap params = new SearchParameterMap(); SearchParameterMap params = new SearchParameterMap();
@ -172,7 +175,7 @@ public class SearchCoordinatorSvcImplTest {
List<Long> pids = createPidSequence(10, 800); List<Long> pids = createPidSequence(10, 800);
Iterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2); Iterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2);
when(mySearchBuider.createQuery(Mockito.same(params))).thenReturn(iter); when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).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));
@ -208,7 +211,7 @@ public class SearchCoordinatorSvcImplTest {
List<Long> pids = createPidSequence(10, 800); List<Long> pids = createPidSequence(10, 800);
SlowIterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2); SlowIterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2);
when(mySearchBuider.createQuery(Mockito.same(params))).thenReturn(iter); when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).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));
@ -236,7 +239,7 @@ public class SearchCoordinatorSvcImplTest {
List<Long> pids = createPidSequence(10, 800); List<Long> pids = createPidSequence(10, 800);
Iterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2); Iterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2);
when(mySearchBuider.createQuery(Mockito.same(params))).thenReturn(iter); when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).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));
@ -286,7 +289,7 @@ public class SearchCoordinatorSvcImplTest {
List<Long> pids = createPidSequence(10, 100); List<Long> pids = createPidSequence(10, 100);
SlowIterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2); SlowIterator<Long> iter = new SlowIterator<Long>(pids.iterator(), 2);
when(mySearchBuider.createQuery(Mockito.same(params))).thenReturn(iter); when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).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));
@ -374,7 +377,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))).thenReturn(pids.iterator()); when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(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));
@ -395,7 +398,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))).thenReturn(pids.iterator()); when(mySearchBuider.createQuery(Mockito.same(params), any(String.class))).thenReturn(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));

View File

@ -7,8 +7,9 @@
</head> </head>
<body> <body>
<form action="" method="get" id="outerForm"> <form action="#" method="get" id="outerForm">
<input type="hidden" id="serverId" name="serverId" th:value="${serverId}"/> <input type="hidden" id="serverId" name="serverId" th:value="${serverId}"/>
<input th:if="${_csrf} != null" type="hidden" th:name="${_csrf.parameterName}" th:value="${_csrf.token}" />
<div th:replace="tmpl-navbar-top :: top" ></div> <div th:replace="tmpl-navbar-top :: top" ></div>