From 2f7751a07914c13168c254b35c63815c5d7694ae Mon Sep 17 00:00:00 2001 From: James Agnew Date: Sun, 4 Mar 2018 12:13:18 -0500 Subject: [PATCH] Move stopwatch into hapi-fhir-base and add timing into to client LoggingInterceptor --- .../fhir/rest/client/api/IHttpResponse.java | 26 ++- .../main/java/ca/uhn/fhir/util/StopWatch.java | 209 ++++++++++++++++++ .../java/ca/uhn/fhir}/util/StopWatchTest.java | 8 +- .../okhttp/client/OkHttpRestfulRequest.java | 8 +- .../okhttp/client/OkHttpRestfulResponse.java | 7 +- .../rest/client/apache/ApacheHttpRequest.java | 6 +- .../client/apache/ApacheHttpResponse.java | 7 +- .../rest/client/impl/BaseHttpResponse.java | 17 ++ .../interceptor/LoggingInterceptor.java | 4 +- .../igpacks/parser/IgPackParserDstu3.java | 2 +- .../fhir/jaxrs/client/JaxRsHttpRequest.java | 76 ++++--- .../fhir/jaxrs/client/JaxRsHttpResponse.java | 9 +- .../ca/uhn/fhir/jpa/dao/BaseHapiFhirDao.java | 16 +- .../fhir/jpa/dao/BaseHapiFhirResourceDao.java | 2 +- .../fhir/jpa/dao/BaseHapiFhirSystemDao.java | 2 +- .../fhir/jpa/dao/BaseSearchParamRegistry.java | 2 +- .../ca/uhn/fhir/jpa/dao/SearchBuilder.java | 2 +- .../jpa/dao/dstu3/FhirSystemDaoDstu3.java | 10 +- .../uhn/fhir/jpa/dao/r4/FhirSystemDaoR4.java | 8 +- .../jpa/search/SearchCoordinatorSvcImpl.java | 2 +- .../BaseSubscriptionInterceptor.java | 2 +- .../SubscriptionCheckingSubscriber.java | 4 +- .../email/JavaMailEmailSender.java | 2 +- .../fhir/jpa/term/BaseHapiTerminologySvc.java | 2 +- .../jpa/term/HapiTerminologySvcDstu3.java | 2 +- .../fhir/jpa/term/HapiTerminologySvcR4.java | 2 +- .../java/ca/uhn/fhir/jpa/util/StopWatch.java | 169 +------------- .../java/ca/uhn/fhir/jpa/dao/BaseJpaTest.java | 2 +- .../dstu3/FhirDaoConcurrencyDstu3Test.java | 2 +- ...rResourceDaoDstu3SearchPageExpiryTest.java | 2 +- .../FhirResourceDaoDstu3ValidateTest.java | 2 +- ...FhirResourceDaoR4SearchPageExpiryTest.java | 2 +- .../dao/r4/FhirResourceDaoR4ValidateTest.java | 2 +- .../provider/r4/ResourceProviderR4Test.java | 2 +- .../jpa/util/jsonpatch/JsonPatchTest.java | 36 --- .../fhir/jpa/util/xmlpatch/XmlPatchTest.java | 35 --- .../rest/client/CapturingInterceptorTest.java | 181 ++++++++------- .../rest/client/LoggingInterceptorTest.java | 6 +- src/changes/changes.xml | 8 +- 39 files changed, 459 insertions(+), 427 deletions(-) create mode 100644 hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java rename {hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa => hapi-fhir-base/src/test/java/ca/uhn/fhir}/util/StopWatchTest.java (95%) create mode 100644 hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/impl/BaseHttpResponse.java delete mode 100644 hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/jsonpatch/JsonPatchTest.java delete mode 100644 hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/xmlpatch/XmlPatchTest.java diff --git a/hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/client/api/IHttpResponse.java b/hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/client/api/IHttpResponse.java index 1f30f56c99e..2801b13e685 100644 --- a/hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/client/api/IHttpResponse.java +++ b/hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/client/api/IHttpResponse.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.rest.client.api; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -20,6 +20,8 @@ package ca.uhn.fhir.rest.client.api; * #L% */ +import ca.uhn.fhir.util.StopWatch; + import java.io.IOException; import java.io.InputStream; import java.io.Reader; @@ -57,7 +59,7 @@ public interface IHttpResponse { *

* Buffering the message entity data allows for multiple invocations of * {@code readEntity(...)} methods on the response instance. - * + * * @since 2.2 */ void bufferEntity() throws IOException; @@ -74,13 +76,13 @@ public interface IHttpResponse { /** * Get map of the response headers and corresponding string values. - * + * * @return response headers as a map header keys and they values. */ Map> getAllHeaders(); /** - * Return all headers in the response with the given type + * Return all headers in the response with the given type */ List getHeaders(String theName); @@ -91,6 +93,15 @@ public interface IHttpResponse { */ String getMimeType(); + /** + * @return Returns a StopWatch that was started right before + * the client request was started. The time returned by this + * client includes any time that was spent within the HTTP + * library (possibly including waiting for a connection, and + * any network activity) + */ + StopWatch getRequestStopWatch(); + /** * @return the native response, depending on the client library used */ @@ -98,14 +109,14 @@ public interface IHttpResponse { /** * Get the status code associated with the response. - * + * * @return the response status code. */ int getStatus(); /** * Get the response status information reason phrase associated with the response. - * + * * @return the reason phrase. */ String getStatusInfo(); @@ -114,5 +125,4 @@ public interface IHttpResponse { * Read the message entity input stream as an InputStream. */ InputStream readEntity() throws IOException; - } diff --git a/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java b/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java new file mode 100644 index 00000000000..57129af54cf --- /dev/null +++ b/hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java @@ -0,0 +1,209 @@ +package ca.uhn.fhir.util; + +import com.google.common.annotations.VisibleForTesting; +import org.apache.commons.lang3.time.DateUtils; + +import java.text.DecimalFormat; +import java.text.NumberFormat; +import java.util.Date; +import java.util.concurrent.TimeUnit; + +/* + * #%L + * HAPI FHIR JPA Server + * %% + * Copyright (C) 2014 - 2018 University Health Network + * %% + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * #L% + */ + +/** + * @since HAPI FHIR 3.3.0 + */ +public class StopWatch { + + private static final NumberFormat DAY_FORMAT = new DecimalFormat("0.0"); + private static final NumberFormat TEN_DAY_FORMAT = new DecimalFormat("0"); + private static Long ourNowForUnitTest; + private long myStarted = now(); + + /** + * Constructor + */ + public StopWatch() { + super(); + } + + /** + * Constructor + * + * @param theStart The time to record as the start for this timer + */ + public StopWatch(Date theStart) { + myStarted = theStart.getTime(); + } + + public String formatThroughput(int theNumOperations, TimeUnit theUnit) { + double throughput = getThroughput(theNumOperations, theUnit); + return new DecimalFormat("0.0").format(throughput); + } + + /** + * Given an amount of something completed so far, and a total amount, calculates how long it will take for something to complete + * + * @param theCompleteToDate The amount so far + * @param theTotal The total (must be higher than theCompleteToDate + * @return A formatted amount of time + */ + public String getEstimatedTimeRemaining(double theCompleteToDate, double theTotal) { + double completeSoFar = theCompleteToDate / theTotal; + double remaining; + if (completeSoFar > 0.5) { + remaining = (1.0 - completeSoFar); + } else { + remaining = (1.0 / completeSoFar); + } + double millis = getMillis(); + long millisRemaining = (long) (millis * remaining); + return formatMillis(millisRemaining); + } + + public long getMillis(Date theNow) { + return theNow.getTime() - myStarted; + } + + public long getMillis() { + long now = now(); + return now - myStarted; + } + + public long getMillisAndRestart() { + long now = now(); + long retVal = now - myStarted; + myStarted = now; + return retVal; + } + + /** + * @param theNumOperations Ok for this to be 0, it will be treated as 1 + */ + public int getMillisPerOperation(int theNumOperations) { + return (int) (((double) getMillis()) / Math.max(1.0, theNumOperations)); + } + + public Date getStartedDate() { + return new Date(myStarted); + } + + public double getThroughput(int theNumOperations, TimeUnit theUnit) { + if (theNumOperations <= 0) { + return 0.0f; + } + + long millisElapsed = Math.max(1, getMillis()); + long periodMillis = theUnit.toMillis(1); + + double numerator = theNumOperations; + double denominator = ((double) millisElapsed) / ((double) periodMillis); + + return numerator / denominator; + } + + public void restart() { + myStarted = now(); + } + + /** + * Formats value in an appropriate format. See {@link #formatMillis(long)}} + * for a description of the format + * + * @see #formatMillis(long) + */ + @Override + public String toString() { + return formatMillis(getMillis()); + } + + /** + * Append a right-aligned and zero-padded numeric value to a `StringBuilder`. + */ + static private void append(StringBuilder tgt, String pfx, int dgt, long val) { + tgt.append(pfx); + if (dgt > 1) { + int pad = (dgt - 1); + for (long xa = val; xa > 9 && pad > 0; xa /= 10) { + pad--; + } + for (int xa = 0; xa < pad; xa++) { + tgt.append('0'); + } + } + tgt.append(val); + } + + /** + * Formats a number of milliseconds for display (e.g. + * in a log file), tailoring the output to how big + * the value actually is. + *

+ * Example outputs: + *

+ * + */ + public static String formatMillis(long val) { + StringBuilder buf = new StringBuilder(20); + if (val < (10 * DateUtils.MILLIS_PER_SECOND)) { + buf.append(val); + buf.append("ms"); + } else if (val >= DateUtils.MILLIS_PER_DAY) { + double days = (double) val / DateUtils.MILLIS_PER_DAY; + if (days >= 10) { + buf.append(TEN_DAY_FORMAT.format(days)); + buf.append(" days"); + } else if (days != 1.0f) { + buf.append(DAY_FORMAT.format(days)); + buf.append(" days"); + } else { + buf.append(DAY_FORMAT.format(days)); + buf.append(" day"); + } + } else { + append(buf, "", 2, ((val % DateUtils.MILLIS_PER_DAY) / DateUtils.MILLIS_PER_HOUR)); + append(buf, ":", 2, ((val % DateUtils.MILLIS_PER_HOUR) / DateUtils.MILLIS_PER_MINUTE)); + append(buf, ":", 2, ((val % DateUtils.MILLIS_PER_MINUTE) / DateUtils.MILLIS_PER_SECOND)); + if (val <= DateUtils.MILLIS_PER_MINUTE) { + append(buf, ".", 3, (val % DateUtils.MILLIS_PER_SECOND)); + } + } + return buf.toString(); + } + + private static long now() { + if (ourNowForUnitTest != null) { + return ourNowForUnitTest; + } + return System.currentTimeMillis(); + } + + @VisibleForTesting + static void setNowForUnitTestForUnitTest(Long theNowForUnitTest) { + ourNowForUnitTest = theNowForUnitTest; + } + +} diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java b/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java similarity index 95% rename from hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java rename to hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java index 8e77eb15639..60d6f691f46 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java +++ b/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java @@ -1,4 +1,4 @@ -package ca.uhn.fhir.jpa.util; +package ca.uhn.fhir.util; import org.apache.commons.lang3.time.DateUtils; import org.hamcrest.Matchers; @@ -33,7 +33,7 @@ public class StopWatchTest { StopWatch sw = new StopWatch(); StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE); - assertEquals("00:00:00.600", sw.getEstimatedTimeRemaining(0.99, 1.0)); + assertEquals("600ms", sw.getEstimatedTimeRemaining(0.99, 1.0)); StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE); assertEquals("00:10:00", sw.getEstimatedTimeRemaining(0.1, 1.0)); @@ -53,7 +53,7 @@ public class StopWatchTest { @Test public void testFormatMillis() { - assertEquals("00:00:01.000", 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:01", StopWatch.formatMillis(DateUtils.MILLIS_PER_MINUTE + DateUtils.MILLIS_PER_SECOND)); assertEquals("01:00:00", StopWatch.formatMillis(DateUtils.MILLIS_PER_HOUR)); @@ -143,7 +143,7 @@ public class StopWatchTest { String string = sw.toString(); ourLog.info(string); - assertThat(string, startsWith("00:00")); + assertThat(string, matchesPattern("^[0-9]{3,4}ms$")); } } diff --git a/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulRequest.java b/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulRequest.java index dd60594a0c9..5b2b68f652a 100644 --- a/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulRequest.java +++ b/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulRequest.java @@ -27,6 +27,7 @@ import java.util.Map; import ca.uhn.fhir.rest.api.RequestTypeEnum; import ca.uhn.fhir.rest.client.api.IHttpRequest; import ca.uhn.fhir.rest.client.api.IHttpResponse; +import ca.uhn.fhir.util.StopWatch; import okhttp3.Call; import okhttp3.Call.Factory; import okhttp3.Request; @@ -65,9 +66,10 @@ public class OkHttpRestfulRequest implements IHttpRequest { @Override public IHttpResponse execute() throws IOException { - myRequestBuilder.method(getHttpVerbName(), myRequestBody); - Call call = myClient.newCall(myRequestBuilder.build()); - return new OkHttpRestfulResponse(call.execute()); + StopWatch responseStopWatch = new StopWatch(); + myRequestBuilder.method(getHttpVerbName(), myRequestBody); + Call call = myClient.newCall(myRequestBuilder.build()); + return new OkHttpRestfulResponse(call.execute(), responseStopWatch); } @Override diff --git a/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulResponse.java b/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulResponse.java index bf9bb61bd79..2714eb8535a 100644 --- a/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulResponse.java +++ b/hapi-fhir-client-okhttp/src/main/java/ca/uhn/fhir/okhttp/client/OkHttpRestfulResponse.java @@ -4,6 +4,8 @@ import java.io.*; import java.util.List; import java.util.Map; +import ca.uhn.fhir.rest.client.impl.BaseHttpResponse; +import ca.uhn.fhir.util.StopWatch; import org.apache.commons.io.IOUtils; import ca.uhn.fhir.rest.api.Constants; @@ -38,13 +40,14 @@ import okhttp3.Response; * * @author Matthew Clarke | matthew.clarke@orionhealth.com | Orion Health */ -public class OkHttpRestfulResponse implements IHttpResponse { +public class OkHttpRestfulResponse extends BaseHttpResponse implements IHttpResponse { private boolean myEntityBuffered = false; private byte[] myEntityBytes; private Response myResponse; - public OkHttpRestfulResponse(Response theResponse) { + public OkHttpRestfulResponse(Response theResponse, StopWatch theResponseStopWatch) { + super(theResponseStopWatch); this.myResponse = theResponse; } diff --git a/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpRequest.java b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpRequest.java index e971828a9d7..555d7ae593d 100644 --- a/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpRequest.java +++ b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpRequest.java @@ -27,10 +27,12 @@ import java.util.LinkedList; import java.util.List; import java.util.Map; +import ca.uhn.fhir.util.StopWatch; import org.apache.commons.io.IOUtils; import org.apache.http.Header; import org.apache.http.HttpEntity; import org.apache.http.HttpEntityEnclosingRequest; +import org.apache.http.HttpResponse; import org.apache.http.client.HttpClient; import org.apache.http.client.methods.HttpRequestBase; import org.apache.http.entity.ContentType; @@ -61,7 +63,9 @@ public class ApacheHttpRequest implements IHttpRequest { @Override public IHttpResponse execute() throws IOException { - return new ApacheHttpResponse(myClient.execute(myRequest)); + StopWatch responseStopWatch = new StopWatch(); + HttpResponse httpResponse = myClient.execute(myRequest); + return new ApacheHttpResponse(httpResponse, responseStopWatch); } @Override diff --git a/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpResponse.java b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpResponse.java index 581e740394b..e50db2e79b9 100644 --- a/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpResponse.java +++ b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/apache/ApacheHttpResponse.java @@ -23,6 +23,8 @@ import java.io.*; import java.nio.charset.Charset; import java.util.*; +import ca.uhn.fhir.rest.client.impl.BaseHttpResponse; +import ca.uhn.fhir.util.StopWatch; import org.apache.commons.io.IOUtils; import org.apache.http.*; import org.apache.http.client.methods.CloseableHttpResponse; @@ -38,7 +40,7 @@ import ca.uhn.fhir.rest.server.exceptions.InternalErrorException; * * @author Peter Van Houte | peter.vanhoute@agfa.com | Agfa Healthcare */ -public class ApacheHttpResponse implements IHttpResponse { +public class ApacheHttpResponse extends BaseHttpResponse implements IHttpResponse { private static final org.slf4j.Logger ourLog = org.slf4j.LoggerFactory.getLogger(ApacheHttpResponse.class); @@ -46,7 +48,8 @@ public class ApacheHttpResponse implements IHttpResponse { private byte[] myEntityBytes; private final HttpResponse myResponse; - public ApacheHttpResponse(HttpResponse theResponse) { + public ApacheHttpResponse(HttpResponse theResponse, StopWatch theResponseStopWatch) { + super(theResponseStopWatch); this.myResponse = theResponse; } diff --git a/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/impl/BaseHttpResponse.java b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/impl/BaseHttpResponse.java new file mode 100644 index 00000000000..812b7a78f65 --- /dev/null +++ b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/impl/BaseHttpResponse.java @@ -0,0 +1,17 @@ +package ca.uhn.fhir.rest.client.impl; + +import ca.uhn.fhir.rest.client.api.IHttpResponse; +import ca.uhn.fhir.util.StopWatch; + +public abstract class BaseHttpResponse implements IHttpResponse { + private final StopWatch myRequestStopWatch; + + public BaseHttpResponse(StopWatch theRequestStopWatch) { + myRequestStopWatch = theRequestStopWatch; + } + + @Override + public StopWatch getRequestStopWatch() { + return myRequestStopWatch; + } +} diff --git a/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/interceptor/LoggingInterceptor.java b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/interceptor/LoggingInterceptor.java index 56c43f4476b..083cf218c73 100644 --- a/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/interceptor/LoggingInterceptor.java +++ b/hapi-fhir-client/src/main/java/ca/uhn/fhir/rest/client/interceptor/LoggingInterceptor.java @@ -115,7 +115,9 @@ public class LoggingInterceptor implements IClientInterceptor { } respLocation = " (" + locationValue + ")"; } - myLog.info("Client response: {}{}", message, respLocation); + + String timing = " in " + theResponse.getRequestStopWatch().toString(); + myLog.info("Client response: {}{}{}", message, respLocation, timing); } if (myLogResponseHeaders) { diff --git a/hapi-fhir-igpacks/src/main/java/ca/uhn/fhir/igpacks/parser/IgPackParserDstu3.java b/hapi-fhir-igpacks/src/main/java/ca/uhn/fhir/igpacks/parser/IgPackParserDstu3.java index acd7447aa7c..a34a408231e 100644 --- a/hapi-fhir-igpacks/src/main/java/ca/uhn/fhir/igpacks/parser/IgPackParserDstu3.java +++ b/hapi-fhir-igpacks/src/main/java/ca/uhn/fhir/igpacks/parser/IgPackParserDstu3.java @@ -23,7 +23,7 @@ package ca.uhn.fhir.igpacks.parser; import ca.uhn.fhir.context.FhirContext; import ca.uhn.fhir.context.FhirVersionEnum; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.Constants; import ca.uhn.fhir.rest.server.exceptions.InternalErrorException; import org.apache.commons.lang3.Validate; diff --git a/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpRequest.java b/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpRequest.java index dfc5b72b185..8842ccd68f2 100644 --- a/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpRequest.java +++ b/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpRequest.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.jaxrs.client; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -20,31 +20,31 @@ package ca.uhn.fhir.jaxrs.client; * #L% */ +import ca.uhn.fhir.rest.api.RequestTypeEnum; +import ca.uhn.fhir.rest.client.api.IHttpRequest; +import ca.uhn.fhir.rest.client.api.IHttpResponse; +import ca.uhn.fhir.util.StopWatch; + +import javax.ws.rs.client.Entity; +import javax.ws.rs.client.Invocation; +import javax.ws.rs.core.Response; import java.util.HashMap; import java.util.LinkedList; import java.util.List; import java.util.Map; -import javax.ws.rs.client.Entity; -import javax.ws.rs.client.Invocation; -import javax.ws.rs.core.Response; - -import ca.uhn.fhir.rest.api.RequestTypeEnum; -import ca.uhn.fhir.rest.client.api.IHttpRequest; -import ca.uhn.fhir.rest.client.api.IHttpResponse; - /** * A Http Request based on JaxRs. This is an adapter around the class * {@link javax.ws.rs.client.Invocation Invocation} - * + * * @author Peter Van Houte | peter.vanhoute@agfa.com | Agfa Healthcare */ public class JaxRsHttpRequest implements IHttpRequest { + private final Map> myHeaders = new HashMap>(); private Invocation.Builder myRequest; private RequestTypeEnum myRequestType; private Entity myEntity; - private final Map> myHeaders = new HashMap>(); public JaxRsHttpRequest(Invocation.Builder theRequest, RequestTypeEnum theRequestType, Entity theEntity) { this.myRequest = theRequest; @@ -61,24 +61,22 @@ public class JaxRsHttpRequest implements IHttpRequest { getRequest().header(theName, theValue); } - /** - * Get the Request - * @return the Request - */ - public Invocation.Builder getRequest() { - return myRequest; + @Override + public IHttpResponse execute() { + StopWatch responseStopWatch = new StopWatch(); + Invocation invocation = getRequest().build(getRequestType().name(), getEntity()); + Response response = invocation.invoke(); + return new JaxRsHttpResponse(response, responseStopWatch); } - /** - * Get the Request Type - * @return the request type - */ - public RequestTypeEnum getRequestType() { - return myRequestType == null ? RequestTypeEnum.GET : myRequestType; + @Override + public Map> getAllHeaders() { + return this.myHeaders; } /** * Get the Entity + * * @return the entity */ public Entity getEntity() { @@ -86,15 +84,17 @@ public class JaxRsHttpRequest implements IHttpRequest { } @Override - public IHttpResponse execute() { - Invocation invocation = getRequest().build(getRequestType().name(), getEntity()); - Response response = invocation.invoke(); - return new JaxRsHttpResponse(response); + public String getHttpVerbName() { + return myRequestType.name(); } - @Override - public Map> getAllHeaders() { - return this.myHeaders; + /** + * Get the Request + * + * @return the Request + */ + public Invocation.Builder getRequest() { + return myRequest; } @Override @@ -103,14 +103,18 @@ public class JaxRsHttpRequest implements IHttpRequest { return null; } + /** + * Get the Request Type + * + * @return the request type + */ + public RequestTypeEnum getRequestType() { + return myRequestType == null ? RequestTypeEnum.GET : myRequestType; + } + @Override public String getUri() { return ""; // TODO: can we get this from somewhere? } - @Override - public String getHttpVerbName() { - return myRequestType.name(); - } - } diff --git a/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpResponse.java b/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpResponse.java index 524aa76fd05..1212d6e7481 100644 --- a/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpResponse.java +++ b/hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpResponse.java @@ -25,7 +25,6 @@ import java.io.IOException; import java.io.InputStream; import java.io.Reader; import java.io.StringReader; -import java.util.Collections; import java.util.List; import java.util.Map; import java.util.Map.Entry; @@ -34,7 +33,8 @@ import java.util.concurrent.ConcurrentHashMap; import javax.ws.rs.core.MediaType; import javax.ws.rs.core.Response; -import org.apache.commons.lang3.ObjectUtils; +import ca.uhn.fhir.rest.client.impl.BaseHttpResponse; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.client.api.IHttpResponse; @@ -42,12 +42,13 @@ import ca.uhn.fhir.rest.client.api.IHttpResponse; * A Http Response based on JaxRs. This is an adapter around the class {@link javax.ws.rs.core.Response Response} * @author Peter Van Houte | peter.vanhoute@agfa.com | Agfa Healthcare */ -public class JaxRsHttpResponse implements IHttpResponse { +public class JaxRsHttpResponse extends BaseHttpResponse implements IHttpResponse { private boolean myBufferedEntity = false; private final Response myResponse; - public JaxRsHttpResponse(Response theResponse) { + public JaxRsHttpResponse(Response theResponse, StopWatch theResponseStopWatch) { + super(theResponseStopWatch); this.myResponse = theResponse; } diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirDao.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirDao.java index bb3ce1e6ec1..8e43c1cb48f 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirDao.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirDao.java @@ -9,9 +9,9 @@ package ca.uhn.fhir.jpa.dao; * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at - * + * * http://www.apache.org/licenses/LICENSE-2.0 - * + * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. @@ -61,6 +61,8 @@ import org.apache.commons.lang3.StringUtils; import org.apache.commons.lang3.Validate; import org.apache.http.NameValuePair; import org.apache.http.client.utils.URLEncodedUtils; +import org.hibernate.Session; +import org.hibernate.internal.SessionImpl; import org.hl7.fhir.instance.model.api.*; import org.hl7.fhir.r4.model.BaseResource; import org.hl7.fhir.r4.model.Bundle.HTTPVerb; @@ -633,6 +635,16 @@ public abstract class BaseHapiFhirDao implements IDao { } } + protected void flushJpaSession() { + SessionImpl session = (SessionImpl) myEntityManager.unwrap(Session.class); + int insertionCount = session.getActionQueue().numberOfInsertions(); + int updateCount = session.getActionQueue().numberOfUpdates(); + + StopWatch sw = new StopWatch(); + myEntityManager.flush(); + ourLog.debug("Session flush took {}ms for {} inserts and {} updates", sw.getMillis(), insertionCount, updateCount); + } + private Set getAllTagDefinitions(ResourceTable theEntity) { HashSet retVal = Sets.newHashSet(); for (ResourceTag next : theEntity.getTags()) { diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java index 4aa6732ec02..8fabeeb5e4b 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirResourceDao.java @@ -32,7 +32,7 @@ import ca.uhn.fhir.jpa.entity.*; import ca.uhn.fhir.jpa.search.DatabaseBackedPagingProvider; import ca.uhn.fhir.jpa.search.PersistedJpaBundleProvider; import ca.uhn.fhir.jpa.util.DeleteConflict; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.jpa.util.jsonpatch.JsonPatchUtils; import ca.uhn.fhir.jpa.util.xmlpatch.XmlPatchUtils; import ca.uhn.fhir.model.api.*; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirSystemDao.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirSystemDao.java index d55c4ba39f3..270a6e32c43 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirSystemDao.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseHapiFhirSystemDao.java @@ -6,7 +6,7 @@ import ca.uhn.fhir.jpa.dao.data.ITermConceptDao; import ca.uhn.fhir.jpa.entity.ForcedId; import ca.uhn.fhir.jpa.entity.ResourceTable; import ca.uhn.fhir.jpa.util.ReindexFailureException; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.RestOperationTypeEnum; import ca.uhn.fhir.rest.api.server.IBundleProvider; import ca.uhn.fhir.rest.api.server.RequestDetails; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseSearchParamRegistry.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseSearchParamRegistry.java index 654b856b574..c5c97fa8252 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseSearchParamRegistry.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/BaseSearchParamRegistry.java @@ -24,7 +24,7 @@ import ca.uhn.fhir.context.FhirContext; import ca.uhn.fhir.context.RuntimeResourceDefinition; import ca.uhn.fhir.context.RuntimeSearchParam; import ca.uhn.fhir.jpa.search.JpaRuntimeSearchParam; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.server.IBundleProvider; import ca.uhn.fhir.util.SearchParameterUtil; import org.apache.commons.lang3.StringUtils; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java index e1a86d6a4e7..0ac09759db7 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/SearchBuilder.java @@ -28,7 +28,7 @@ import ca.uhn.fhir.jpa.search.JpaRuntimeSearchParam; import ca.uhn.fhir.jpa.term.IHapiTerminologySvc; import ca.uhn.fhir.jpa.term.VersionIndependentConcept; import ca.uhn.fhir.jpa.util.BaseIterator; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.model.api.*; import ca.uhn.fhir.model.base.composite.BaseCodingDt; import ca.uhn.fhir.model.base.composite.BaseIdentifierDt; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/dstu3/FhirSystemDaoDstu3.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/dstu3/FhirSystemDaoDstu3.java index 7b93ff30239..64ccf5b564d 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/dstu3/FhirSystemDaoDstu3.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/dstu3/FhirSystemDaoDstu3.java @@ -28,7 +28,7 @@ import java.util.Map.Entry; import javax.persistence.TypedQuery; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.param.ParameterUtil; import org.apache.commons.lang3.Validate; import org.apache.http.NameValuePair; @@ -538,13 +538,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao { } } - SessionImpl session = (SessionImpl) myEntityManager.unwrap(Session.class); - int insertionCount = session.getActionQueue().numberOfInsertions(); - int updateCount = session.getActionQueue().numberOfUpdates(); - - StopWatch sw = new StopWatch(); - myEntityManager.flush(); - ourLog.debug("Session flush took {}ms for {} inserts and {} updates", sw.getMillis(), insertionCount, updateCount); + flushJpaSession(); /* * Double check we didn't allow any duplicates we shouldn't have diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/r4/FhirSystemDaoR4.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/r4/FhirSystemDaoR4.java index 1eb4feddd78..f4e2e05f1e4 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/r4/FhirSystemDaoR4.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/r4/FhirSystemDaoR4.java @@ -29,6 +29,7 @@ import ca.uhn.fhir.jpa.entity.ResourceTable; import ca.uhn.fhir.jpa.entity.TagDefinition; import ca.uhn.fhir.jpa.provider.ServletSubRequestDetails; import ca.uhn.fhir.jpa.util.DeleteConflict; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.model.api.ResourceMetadataKeyEnum; import ca.uhn.fhir.parser.DataFormatException; import ca.uhn.fhir.parser.IParser; @@ -547,8 +548,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao { } } - myEntityManager.flush(); - ourLog.debug("Session flush took {}ms for {} inserts and {} updates", sw.getMillis(), insertionCount, updateCount); + flushJpaSession(); /* * Double check we didn't allow any duplicates we shouldn't have @@ -619,9 +619,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao { TypedQuery q = myEntityManager.createQuery(sql, TagDefinition.class); List tagDefinitions = q.getResultList(); - Meta retVal = toMeta(tagDefinitions); - - return retVal; + return toMeta(tagDefinitions); } private String performIdSubstitutionsInMatchUrl(Map theIdSubstitutions, String theMatchUrl) { diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java index f025610029d..8ffef936f9f 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/search/SearchCoordinatorSvcImpl.java @@ -29,7 +29,7 @@ import ca.uhn.fhir.jpa.dao.data.ISearchDao; import ca.uhn.fhir.jpa.dao.data.ISearchIncludeDao; import ca.uhn.fhir.jpa.dao.data.ISearchResultDao; import ca.uhn.fhir.jpa.entity.*; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.model.api.Include; import ca.uhn.fhir.rest.api.CacheControlDirective; import ca.uhn.fhir.rest.api.Constants; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionInterceptor.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionInterceptor.java index ddee01b6964..a22396e22ff 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionInterceptor.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionInterceptor.java @@ -28,7 +28,7 @@ import ca.uhn.fhir.jpa.dao.IFhirResourceDao; import ca.uhn.fhir.jpa.dao.SearchParameterMap; import ca.uhn.fhir.jpa.provider.ServletSubRequestDetails; import ca.uhn.fhir.jpa.util.JpaConstants; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.RestOperationTypeEnum; import ca.uhn.fhir.rest.api.server.IBundleProvider; import ca.uhn.fhir.rest.api.server.RequestDetails; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/SubscriptionCheckingSubscriber.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/SubscriptionCheckingSubscriber.java index e87bf9998db..054da70044b 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/SubscriptionCheckingSubscriber.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/SubscriptionCheckingSubscriber.java @@ -102,13 +102,13 @@ public class SubscriptionCheckingSubscriber extends BaseSubscriptionSubscriber { IBundleProvider results = performSearch(criteria); - ourLog.info("Subscription check found {} results for query: {}", results.size(), criteria); + ourLog.debug("Subscription check found {} results for query: {}", results.size(), criteria); if (results.size() == 0) { continue; } - ourLog.info("Found match: queueing rest-hook notification for resource: {}", id.toUnqualifiedVersionless().getValue()); + ourLog.debug("Found match: queueing rest-hook notification for resource: {}", id.toUnqualifiedVersionless().getValue()); ResourceDeliveryMessage deliveryMsg = new ResourceDeliveryMessage(); deliveryMsg.setPayload(getContext(), msg.getNewPayload(getContext())); diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/email/JavaMailEmailSender.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/email/JavaMailEmailSender.java index 8daf3a375e2..467c62b4090 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/email/JavaMailEmailSender.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/email/JavaMailEmailSender.java @@ -20,7 +20,7 @@ package ca.uhn.fhir.jpa.subscription.email; * #L% */ -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.Constants; import ca.uhn.fhir.rest.server.exceptions.InternalErrorException; import org.apache.commons.lang3.StringUtils; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/BaseHapiTerminologySvc.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/BaseHapiTerminologySvc.java index 1215f057e30..af73596e4e4 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/BaseHapiTerminologySvc.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/BaseHapiTerminologySvc.java @@ -47,7 +47,7 @@ import ca.uhn.fhir.jpa.dao.DaoConfig; import ca.uhn.fhir.jpa.dao.data.*; import ca.uhn.fhir.jpa.entity.*; import ca.uhn.fhir.jpa.entity.TermConceptParentChildLink.RelationshipTypeEnum; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.server.exceptions.InvalidRequestException; import ca.uhn.fhir.rest.server.exceptions.UnprocessableEntityException; import ca.uhn.fhir.util.ObjectUtil; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcDstu3.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcDstu3.java index 03c6a621b81..6170fdc703c 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcDstu3.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcDstu3.java @@ -7,7 +7,7 @@ import ca.uhn.fhir.jpa.entity.ResourceTable; import ca.uhn.fhir.jpa.entity.TermCodeSystem; import ca.uhn.fhir.jpa.entity.TermCodeSystemVersion; import ca.uhn.fhir.jpa.entity.TermConcept; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.server.RequestDetails; import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException; import ca.uhn.fhir.rest.server.exceptions.InternalErrorException; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcR4.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcR4.java index aa2f12dd3d3..fa061da8d7a 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcR4.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/term/HapiTerminologySvcR4.java @@ -7,7 +7,7 @@ import ca.uhn.fhir.jpa.entity.ResourceTable; import ca.uhn.fhir.jpa.entity.TermCodeSystem; import ca.uhn.fhir.jpa.entity.TermCodeSystemVersion; import ca.uhn.fhir.jpa.entity.TermConcept; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.server.RequestDetails; import ca.uhn.fhir.rest.server.exceptions.BaseServerResponseException; import ca.uhn.fhir.rest.server.exceptions.InternalErrorException; diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java index bc5a21668fb..a68116e6000 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java @@ -1,13 +1,5 @@ package ca.uhn.fhir.jpa.util; -import com.google.common.annotations.VisibleForTesting; -import org.apache.commons.lang3.time.DateUtils; - -import java.text.DecimalFormat; -import java.text.NumberFormat; -import java.util.Date; -import java.util.concurrent.TimeUnit; - /* * #%L * HAPI FHIR JPA Server @@ -28,159 +20,10 @@ import java.util.concurrent.TimeUnit; * #L% */ -public class StopWatch { - - private static final NumberFormat DAY_FORMAT = new DecimalFormat("0.0"); - private static final NumberFormat TEN_DAY_FORMAT = new DecimalFormat("0"); - private static Long ourNowForUnitTest; - private long myStarted = now(); - - /** - * Constructor - */ - public StopWatch() { - super(); - } - - /** - * Constructor - * - * @param theStart The time to record as the start for this timer - */ - public StopWatch(Date theStart) { - myStarted = theStart.getTime(); - } - - public String formatThroughput(int theNumOperations, TimeUnit theUnit) { - double throughput = getThroughput(theNumOperations, theUnit); - return new DecimalFormat("0.0").format(throughput); - } - - /** - * Given an amount of something completed so far, and a total amount, calculates how long it will take for something to complete - * - * @param theCompleteToDate The amount so far - * @param theTotal The total (must be higher than theCompleteToDate - * @return A formatted amount of time - */ - public String getEstimatedTimeRemaining(double theCompleteToDate, double theTotal) { - double completeSoFar = theCompleteToDate / theTotal; - double remaining; - if (completeSoFar > 0.5) { - remaining = (1.0 - completeSoFar); - } else { - remaining = (1.0 / completeSoFar); - } - double millis = getMillis(); - long millisRemaining = (long) (millis * remaining); - return formatMillis(millisRemaining); - } - - public long getMillis(Date theNow) { - return theNow.getTime() - myStarted; - } - - public long getMillis() { - long now = now(); - return now - myStarted; - } - - public long getMillisAndRestart() { - long now = now(); - long retVal = now - myStarted; - myStarted = now; - return retVal; - } - - /** - * @param theNumOperations Ok for this to be 0, it will be treated as 1 - */ - public int getMillisPerOperation(int theNumOperations) { - return (int) (((double) getMillis()) / Math.max(1.0, theNumOperations)); - } - - public Date getStartedDate() { - return new Date(myStarted); - } - - public double getThroughput(int theNumOperations, TimeUnit theUnit) { - if (theNumOperations <= 0) { - return 0.0f; - } - - long millisElapsed = Math.max(1, getMillis()); - long periodMillis = theUnit.toMillis(1); - - double numerator = theNumOperations; - double denominator = ((double) millisElapsed) / ((double) periodMillis); - - return numerator / denominator; - } - - public void restart() { - myStarted = now(); - } - - /** - * Formats value in the format [DD d ]HH:mm:ss.SSSS - */ - @Override - public String toString() { - 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); - } - - static public String formatMillis(long val) { - StringBuilder buf = new StringBuilder(20); - 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; - } - +/** + * @deprecated Use {@link ca.uhn.fhir.util.StopWatch} instead + */ +@Deprecated +public class StopWatch extends ca.uhn.fhir.util.StopWatch { + // this just exists since existing code may depend on it } diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/BaseJpaTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/BaseJpaTest.java index 3c19c497fa7..dd0730869a6 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/BaseJpaTest.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/BaseJpaTest.java @@ -6,7 +6,7 @@ import ca.uhn.fhir.jpa.provider.SystemProviderDstu2Test; import ca.uhn.fhir.jpa.search.ISearchCoordinatorSvc; import ca.uhn.fhir.jpa.sp.ISearchParamPresenceSvc; import ca.uhn.fhir.jpa.term.VersionIndependentConcept; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.model.dstu2.resource.Bundle; import ca.uhn.fhir.model.dstu2.resource.Bundle.Entry; import ca.uhn.fhir.rest.api.server.IBundleProvider; diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirDaoConcurrencyDstu3Test.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirDaoConcurrencyDstu3Test.java index d6c27cb0334..fd0624ae78f 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirDaoConcurrencyDstu3Test.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirDaoConcurrencyDstu3Test.java @@ -1,7 +1,7 @@ package ca.uhn.fhir.jpa.dao.dstu3; import ca.uhn.fhir.jpa.dao.DaoConfig; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.server.IBundleProvider; import ca.uhn.fhir.util.TestUtil; import com.phloc.commons.compare.ReverseComparator; diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3SearchPageExpiryTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3SearchPageExpiryTest.java index 95d9e68d559..ee4f62ab945 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3SearchPageExpiryTest.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3SearchPageExpiryTest.java @@ -6,7 +6,7 @@ import ca.uhn.fhir.jpa.dao.data.ISearchDao; import ca.uhn.fhir.jpa.dao.r4.FhirResourceDaoR4SearchPageExpiryTest; import ca.uhn.fhir.jpa.entity.Search; import ca.uhn.fhir.jpa.search.StaleSearchDeletingSvcImpl; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.server.IBundleProvider; import ca.uhn.fhir.rest.param.StringParam; import org.apache.commons.lang3.Validate; diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3ValidateTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3ValidateTest.java index 3442f7cc87d..87969b57c10 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3ValidateTest.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/dstu3/FhirResourceDaoDstu3ValidateTest.java @@ -15,7 +15,7 @@ import org.hl7.fhir.instance.model.api.IBaseResource; import org.hl7.fhir.instance.model.api.IIdType; import org.junit.*; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.*; import ca.uhn.fhir.rest.server.exceptions.*; import ca.uhn.fhir.util.TestUtil; diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4SearchPageExpiryTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4SearchPageExpiryTest.java index 48dd7d48d59..a03be5a948c 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4SearchPageExpiryTest.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4SearchPageExpiryTest.java @@ -5,7 +5,7 @@ import ca.uhn.fhir.jpa.dao.SearchParameterMap; import ca.uhn.fhir.jpa.dao.data.ISearchDao; import ca.uhn.fhir.jpa.entity.Search; import ca.uhn.fhir.jpa.search.StaleSearchDeletingSvcImpl; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.server.IBundleProvider; import ca.uhn.fhir.rest.param.StringParam; import org.apache.commons.lang3.Validate; diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4ValidateTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4ValidateTest.java index 0658d70d633..8c5fea7921d 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4ValidateTest.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/dao/r4/FhirResourceDaoR4ValidateTest.java @@ -15,7 +15,7 @@ import org.hl7.fhir.instance.model.api.IBaseResource; import org.hl7.fhir.instance.model.api.IIdType; import org.junit.*; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.rest.api.*; import ca.uhn.fhir.rest.server.exceptions.*; import ca.uhn.fhir.util.TestUtil; diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/ResourceProviderR4Test.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/ResourceProviderR4Test.java index eb3a2491ec5..f76b72a9462 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/ResourceProviderR4Test.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/provider/r4/ResourceProviderR4Test.java @@ -5,7 +5,7 @@ import ca.uhn.fhir.jpa.dao.DaoConfig; import ca.uhn.fhir.jpa.entity.ResourceHistoryTable; import ca.uhn.fhir.jpa.entity.Search; import ca.uhn.fhir.jpa.search.SearchCoordinatorSvcImpl; -import ca.uhn.fhir.jpa.util.StopWatch; +import ca.uhn.fhir.util.StopWatch; import ca.uhn.fhir.model.api.TemporalPrecisionEnum; import ca.uhn.fhir.model.primitive.InstantDt; import ca.uhn.fhir.model.primitive.UriDt; diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/jsonpatch/JsonPatchTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/jsonpatch/JsonPatchTest.java deleted file mode 100644 index fda48565f38..00000000000 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/jsonpatch/JsonPatchTest.java +++ /dev/null @@ -1,36 +0,0 @@ -package ca.uhn.fhir.jpa.util.jsonpatch; - -import static org.junit.Assert.*; - -import org.hl7.fhir.dstu3.model.Patient; -import org.junit.AfterClass; -import org.junit.Test; - -import ca.uhn.fhir.context.FhirContext; -import ca.uhn.fhir.util.TestUtil; - -public class JsonPatchTest { - - @AfterClass - public static void afterClassClearContext() { - TestUtil.clearAllStaticFieldsForUnitTest(); - } - - private static FhirContext ourCtx = FhirContext.forDstu3(); - - @Test - public void testPatchReplace() { - Patient p = new Patient(); - p.setActive(true); - - //@formatter:off - String patchBody = "[\n" + - " { \"op\":\"replace\", \"path\":\"/active\", \"value\":false }\n" + - "]"; - //@formatter:on - - Patient dest = JsonPatchUtils.apply(ourCtx, p, patchBody); - assertEquals(false, dest.getActive()); - } - -} diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/xmlpatch/XmlPatchTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/xmlpatch/XmlPatchTest.java deleted file mode 100644 index c7e6a8054a7..00000000000 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/xmlpatch/XmlPatchTest.java +++ /dev/null @@ -1,35 +0,0 @@ -package ca.uhn.fhir.jpa.util.xmlpatch; - -import static org.junit.Assert.assertEquals; - -import org.hl7.fhir.dstu3.model.Patient; -import org.junit.AfterClass; -import org.junit.Test; - -import ca.uhn.fhir.context.FhirContext; -import ca.uhn.fhir.jpa.util.xmlpatch.XmlPatchUtils; -import ca.uhn.fhir.util.TestUtil; - -public class XmlPatchTest { - - @AfterClass - public static void afterClassClearContext() { - TestUtil.clearAllStaticFieldsForUnitTest(); - } - - private static FhirContext ourCtx = FhirContext.forDstu3(); - - @Test - public void testPatchReplace() { - Patient p = new Patient(); - p.setActive(true); - - //@formatter:off - String patchBody = "false"; - //@formatter:on - - Patient dest = XmlPatchUtils.apply(ourCtx, p, patchBody); - assertEquals(false, dest.getActive()); - } - -} diff --git a/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/CapturingInterceptorTest.java b/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/CapturingInterceptorTest.java index 7e297f7962a..c57dc79f19a 100644 --- a/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/CapturingInterceptorTest.java +++ b/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/CapturingInterceptorTest.java @@ -5,143 +5,138 @@ import ca.uhn.fhir.rest.client.api.IHttpRequest; import ca.uhn.fhir.rest.client.api.IHttpResponse; import ca.uhn.fhir.rest.client.interceptor.CapturingInterceptor; import ca.uhn.fhir.rest.server.exceptions.InternalErrorException; +import ca.uhn.fhir.util.StopWatch; import org.apache.commons.io.IOUtils; -import org.apache.http.HttpRequest; import org.apache.http.HttpResponse; import org.apache.http.HttpStatus; import org.apache.http.HttpVersion; -import org.apache.http.entity.BasicHttpEntity; import org.apache.http.entity.InputStreamEntity; import org.apache.http.entity.StringEntity; -import org.apache.http.message.BasicHttpRequest; import org.apache.http.message.BasicHttpResponse; -import org.junit.After; import org.junit.Rule; import org.junit.Test; import org.junit.rules.ExpectedException; -import org.mockito.Spy; import java.io.IOException; import java.nio.charset.Charset; import static org.hamcrest.CoreMatchers.equalTo; -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.assertNull; -import static org.junit.Assert.assertThat; +import static org.junit.Assert.*; import static org.mockito.Mockito.*; public class CapturingInterceptorTest { - @Rule - public ExpectedException thrown = ExpectedException.none(); + @Rule + public ExpectedException thrown = ExpectedException.none(); + @Test + public void testClear() { + IHttpRequest expectedRequest = mock(IHttpRequest.class); + IHttpResponse expectedResponse = mock(IHttpResponse.class); + Object response = mock(Object.class); + when(expectedResponse.getResponse()).thenReturn(response); - @Test - public void testRequest() { - IHttpRequest expectedRequest = mock(IHttpRequest.class); + CapturingInterceptor interceptor = new CapturingInterceptor(); + interceptor.interceptResponse(expectedResponse); + interceptor.interceptRequest(expectedRequest); - CapturingInterceptor interceptor = new CapturingInterceptor(); - interceptor.interceptRequest(expectedRequest); + assertEquals(expectedRequest, interceptor.getLastRequest()); + assertEquals(expectedResponse, interceptor.getLastResponse()); - assertEquals(expectedRequest, interceptor.getLastRequest()); - } + interceptor.clear(); - @Test - public void testResponse() throws Exception { - IHttpResponse expectedResponse = mock(IHttpResponse.class); - doNothing().when(expectedResponse).bufferEntity(); + assertNull(interceptor.getLastRequest()); + assertNull(interceptor.getLastResponse()); + } - CapturingInterceptor interceptor = new CapturingInterceptor(); - interceptor.interceptResponse(expectedResponse); + @Test + public void testRequest() { + IHttpRequest expectedRequest = mock(IHttpRequest.class); - assertEquals(expectedResponse, interceptor.getLastResponse()); - verify(expectedResponse).bufferEntity(); - } + CapturingInterceptor interceptor = new CapturingInterceptor(); + interceptor.interceptRequest(expectedRequest); - @Test - public void testResponseException() throws Exception { - IHttpResponse response = mock(IHttpResponse.class); - IOException expectedCause = new IOException(); - doThrow(expectedCause).when(response).bufferEntity(); + assertEquals(expectedRequest, interceptor.getLastRequest()); + } - thrown.expect(InternalErrorException.class); - thrown.expectMessage("Unable to buffer the entity for capturing"); - thrown.expectCause(equalTo(expectedCause)); + @Test + public void testResponse() throws Exception { + IHttpResponse expectedResponse = mock(IHttpResponse.class); + doNothing().when(expectedResponse).bufferEntity(); - CapturingInterceptor interceptor = new CapturingInterceptor(); - interceptor.interceptResponse(response); - } + CapturingInterceptor interceptor = new CapturingInterceptor(); + interceptor.interceptResponse(expectedResponse); - @Test - public void testResponseBufferApache() throws Exception{ - HttpResponse response = new BasicHttpResponse(HttpVersion.HTTP_1_1, HttpStatus.SC_OK, "OK"); - response.setEntity(new InputStreamEntity(IOUtils.toInputStream("Some content", Charset.defaultCharset()))); - IHttpResponse expectedResponse = spy(new ApacheHttpResponse(response)); + assertEquals(expectedResponse, interceptor.getLastResponse()); + verify(expectedResponse).bufferEntity(); + } - CapturingInterceptor interceptor = new CapturingInterceptor(); - interceptor.interceptResponse(expectedResponse); - IHttpResponse actualResponse = interceptor.getLastResponse(); + @Test + public void testResponseBufferApache() throws Exception { + StopWatch responseStopWatch = new StopWatch(); + HttpResponse response = new BasicHttpResponse(HttpVersion.HTTP_1_1, HttpStatus.SC_OK, "OK"); + response.setEntity(new InputStreamEntity(IOUtils.toInputStream("Some content", Charset.defaultCharset()))); + IHttpResponse expectedResponse = spy(new ApacheHttpResponse(response, responseStopWatch)); - assertEquals(expectedResponse, actualResponse); - assertThat("Some content", equalTo(IOUtils.toString(actualResponse.createReader()))); - verify(expectedResponse).bufferEntity(); + CapturingInterceptor interceptor = new CapturingInterceptor(); + interceptor.interceptResponse(expectedResponse); + IHttpResponse actualResponse = interceptor.getLastResponse(); - //A second call should not throw an exception (InpuStreamEntity is not repeatable) - IOUtils.toString(actualResponse.createReader()); - } + assertEquals(expectedResponse, actualResponse); + assertThat("Some content", equalTo(IOUtils.toString(actualResponse.createReader()))); + verify(expectedResponse).bufferEntity(); - @Test - public void testResponseRepeatable() throws Exception{ - HttpResponse response = new BasicHttpResponse(HttpVersion.HTTP_1_1, HttpStatus.SC_OK, "OK"); - response.setEntity(new StringEntity("Some content")); - IHttpResponse expectedResponse = spy(new ApacheHttpResponse(response)); + //A second call should not throw an exception (InpuStreamEntity is not repeatable) + IOUtils.toString(actualResponse.createReader()); + } - CapturingInterceptor interceptor = new CapturingInterceptor(); - interceptor.interceptResponse(expectedResponse); - IHttpResponse actualResponse = interceptor.getLastResponse(); + @Test + public void testResponseBufferOther() throws Exception { + Object response = mock(Object.class); + IHttpResponse expectedResponse = mock(IHttpResponse.class); + when(expectedResponse.getResponse()).thenReturn(response); + doNothing().when(expectedResponse).bufferEntity(); - assertEquals(expectedResponse, actualResponse); - assertThat("Some content", equalTo(IOUtils.toString(actualResponse.createReader()))); - verify(expectedResponse, times(0)).bufferEntity(); + CapturingInterceptor interceptor = new CapturingInterceptor(); + interceptor.interceptResponse(expectedResponse); + IHttpResponse actualResponse = interceptor.getLastResponse(); - //A second call should not throw an exception (StringEntity is repeatable) - IOUtils.toString(actualResponse.createReader()); - } + assertEquals(expectedResponse, actualResponse); + verify(expectedResponse).bufferEntity(); + } - @Test - public void testResponseBufferOther() throws Exception { - Object response = mock(Object.class); - IHttpResponse expectedResponse = mock(IHttpResponse.class); - when(expectedResponse.getResponse()).thenReturn(response); - doNothing().when(expectedResponse).bufferEntity(); + @Test + public void testResponseException() throws Exception { + IHttpResponse response = mock(IHttpResponse.class); + IOException expectedCause = new IOException(); + doThrow(expectedCause).when(response).bufferEntity(); - CapturingInterceptor interceptor = new CapturingInterceptor(); - interceptor.interceptResponse(expectedResponse); - IHttpResponse actualResponse = interceptor.getLastResponse(); + thrown.expect(InternalErrorException.class); + thrown.expectMessage("Unable to buffer the entity for capturing"); + thrown.expectCause(equalTo(expectedCause)); - assertEquals(expectedResponse, actualResponse); - verify(expectedResponse).bufferEntity(); - } + CapturingInterceptor interceptor = new CapturingInterceptor(); + interceptor.interceptResponse(response); + } - @Test - public void testClear(){ - IHttpRequest expectedRequest = mock(IHttpRequest.class); - IHttpResponse expectedResponse = mock(IHttpResponse.class); - Object response = mock(Object.class); - when(expectedResponse.getResponse()).thenReturn(response); + @Test + public void testResponseRepeatable() throws Exception { + StopWatch responseStopWatch = new StopWatch(); + HttpResponse response = new BasicHttpResponse(HttpVersion.HTTP_1_1, HttpStatus.SC_OK, "OK"); + response.setEntity(new StringEntity("Some content")); + IHttpResponse expectedResponse = spy(new ApacheHttpResponse(response, responseStopWatch)); - CapturingInterceptor interceptor = new CapturingInterceptor(); - interceptor.interceptResponse(expectedResponse); - interceptor.interceptRequest(expectedRequest); + CapturingInterceptor interceptor = new CapturingInterceptor(); + interceptor.interceptResponse(expectedResponse); + IHttpResponse actualResponse = interceptor.getLastResponse(); - assertEquals(expectedRequest, interceptor.getLastRequest()); - assertEquals(expectedResponse, interceptor.getLastResponse()); + assertEquals(expectedResponse, actualResponse); + assertThat("Some content", equalTo(IOUtils.toString(actualResponse.createReader()))); + verify(expectedResponse, times(0)).bufferEntity(); - interceptor.clear(); - - assertNull(interceptor.getLastRequest()); - assertNull(interceptor.getLastResponse()); - } + //A second call should not throw an exception (StringEntity is repeatable) + IOUtils.toString(actualResponse.createReader()); + } } diff --git a/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/LoggingInterceptorTest.java b/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/LoggingInterceptorTest.java index 6e7f3c6d413..8eff0b9e38e 100644 --- a/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/LoggingInterceptorTest.java +++ b/hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/LoggingInterceptorTest.java @@ -66,7 +66,7 @@ public class LoggingInterceptorTest { } @Test - public void testLoggerNonVerbose() throws Exception { + public void testLoggerNonVerbose() { System.out.println("Starting testLogger"); IGenericClient client = ourCtx.newRestfulGenericClient("http://localhost:" + ourPort); ourCtx.getRestfulClientFactory().setServerValidationMode(ServerValidationModeEnum.NEVER); @@ -85,13 +85,13 @@ public class LoggingInterceptorTest { System.out.flush(); return formattedMessage.contains("Client request: GET http://localhost:" + ourPort + "/Patient/1 HTTP/1.1") || - formattedMessage.contains("Client response: HTTP 200 OK (Patient/1/_history/1)"); + formattedMessage.contains("Client response: HTTP 200 OK (Patient/1/_history/1) in "); } })); } @Test - public void testLoggerVerbose() throws Exception { + public void testLoggerVerbose() { System.out.println("Starting testLogger"); IGenericClient client = ourCtx.newRestfulGenericClient("http://localhost:" + ourPort); ourCtx.getRestfulClientFactory().setServerValidationMode(ServerValidationModeEnum.NEVER); diff --git a/src/changes/changes.xml b/src/changes/changes.xml index c1e28a91f2d..c545a6268eb 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -156,7 +156,9 @@ A number of info level log lines have been reduced to debug level in the JPA server, in - order to reduce contention during heavy loads. + order to reduce contention during heavy loads and reduce the amount of noise + in log files overall. A typical server should now see far less logging coming + from HAPI, at least at the INFO level. JPA server now correctly indexes custom search parameters which @@ -194,6 +196,10 @@ could be output by the parser's encode methods. Thanks to Frank Tao for supplying a test case! + + The client LoggingInterceptor now includes the number of + milliseconds spent performing each call that is logged. +