Merge branch 'master' of github.com:jamesagnew/hapi-fhir

hapi-fhir-base/src/main/java/ca/uhn/fhir/rest/client/api/IHttpResponse.java

@@ -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;
@@ -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
 	 */
@@ -114,5 +125,4 @@ public interface IHttpResponse {
 	 * Read the message entity input stream as an InputStream.
 	 */
 	InputStream readEntity() throws IOException;
-
 }

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

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$"));
 	}
 
 }

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 {
+		 StopWatch responseStopWatch = new StopWatch();
 		 myRequestBuilder.method(getHttpVerbName(), myRequestBody);
 		 Call call = myClient.newCall(myRequestBuilder.build());
-        return new OkHttpRestfulResponse(call.execute());
+		 return new OkHttpRestfulResponse(call.execute(), responseStopWatch);
     }
 
     @Override

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;
 	}
 

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

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;
 	}
 

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;
+	}
+}

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) {

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;

hapi-fhir-jaxrsserver-base/src/main/java/ca/uhn/fhir/jaxrs/client/JaxRsHttpRequest.java

@@ -20,18 +20,18 @@ package ca.uhn.fhir.jaxrs.client;
  * #L%
  */
 
-import java.util.HashMap;
+import ca.uhn.fhir.rest.api.RequestTypeEnum;
-import java.util.LinkedList;
+import ca.uhn.fhir.rest.client.api.IHttpRequest;
-import java.util.List;
+import ca.uhn.fhir.rest.client.api.IHttpResponse;
-import java.util.Map;
+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 ca.uhn.fhir.rest.api.RequestTypeEnum;
+import java.util.LinkedList;
-import ca.uhn.fhir.rest.client.api.IHttpRequest;
+import java.util.List;
-import ca.uhn.fhir.rest.client.api.IHttpResponse;
+import java.util.Map;
 
 /**
  * A Http Request based on JaxRs. This is an adapter around the class
@@ -41,10 +41,10 @@ import ca.uhn.fhir.rest.client.api.IHttpResponse;
  */
 public class JaxRsHttpRequest implements IHttpRequest {
 
+	private final Map<String, List<String>> myHeaders = new HashMap<String, List<String>>();
 	private Invocation.Builder myRequest;
 	private RequestTypeEnum myRequestType;
 	private Entity<?> myEntity;
-	private final Map<String, List<String>> myHeaders = new HashMap<String, List<String>>();
 
 	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);
 	}
 
-	/**
+	@Override
-	 * Get the Request
+	public IHttpResponse execute() {
-	 * @return the Request
+		StopWatch responseStopWatch = new StopWatch();
-	 */
+		Invocation invocation = getRequest().build(getRequestType().name(), getEntity());
-	public Invocation.Builder getRequest() {
+		Response response = invocation.invoke();
-		return myRequest;
+		return new JaxRsHttpResponse(response, responseStopWatch);
 	}
 
-	/**
+	@Override
-	 * Get the Request Type
+	public Map<String, List<String>> getAllHeaders() {
-	 * @return the request type
+		return this.myHeaders;
-	 */
-	public RequestTypeEnum getRequestType() {
-		return myRequestType == null ? RequestTypeEnum.GET : myRequestType;
 	}
 
 	/**
 	 * Get the Entity
+	 *
 	 * @return the entity
 	 */
 	public Entity<?> getEntity() {
@@ -86,15 +84,17 @@ public class JaxRsHttpRequest implements IHttpRequest {
 	}
 
 	@Override
-	public IHttpResponse execute() {
+	public String getHttpVerbName() {
-		Invocation invocation = getRequest().build(getRequestType().name(), getEntity());
+		return myRequestType.name();
-		Response response = invocation.invoke();
-		return new JaxRsHttpResponse(response);
 	}
 
-	@Override
+	/**
-	public Map<String, List<String>> getAllHeaders() {
+	 * Get the Request
-		return this.myHeaders;
+	 *
+	 * @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();
-	}
-
 }

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;
 	}
 

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

@@ -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;
@@ -640,6 +642,16 @@ public abstract class BaseHapiFhirDao<T extends IBaseResource> 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<TagDefinition> getAllTagDefinitions(ResourceTable theEntity) {
 		HashSet<TagDefinition> retVal = Sets.newHashSet();
 		for (ResourceTag next : theEntity.getTags()) {

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

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;

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;

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;

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<Bundle, Meta> {
 			}
 		}
 
-		SessionImpl session = (SessionImpl) myEntityManager.unwrap(Session.class);
+		flushJpaSession();
-		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);
 
 		/*
 		 * Double check we didn't allow any duplicates we shouldn't have

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<Bundle, Meta> {
 			}
 		}
 
-		myEntityManager.flush();
+		flushJpaSession();
-		ourLog.debug("Session flush took {}ms for {} inserts and {} updates", sw.getMillis(), insertionCount, updateCount);
 
 		/*
 		 * Double check we didn't allow any duplicates we shouldn't have
@@ -619,9 +619,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao<Bundle, Meta> {
 		TypedQuery<TagDefinition> q = myEntityManager.createQuery(sql, TagDefinition.class);
 		List<TagDefinition> tagDefinitions = q.getResultList();
 
-		Meta retVal = toMeta(tagDefinitions);
+		return toMeta(tagDefinitions);
-
-		return retVal;
 	}
 
 	private String performIdSubstitutionsInMatchUrl(Map<IdType, IdType> theIdSubstitutions, String theMatchUrl) {

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;

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;

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()));

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;

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;

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;

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;

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 {
+/**
-
+ * @deprecated Use {@link ca.uhn.fhir.util.StopWatch} instead
-	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() {
+@Deprecated
-		super();
+public class StopWatch extends ca.uhn.fhir.util.StopWatch {
-	}
+	// this just exists since existing code may depend on it
-
-	/**
-	 * 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;
-	}
-
 }

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;

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;

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;

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;

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;

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;

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;

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/jsonpatch/JsonPatchTest.java

@@ -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());
-	}
-	
-}

hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/xmlpatch/XmlPatchTest.java

@@ -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 = "<?xml version=\"1.0\" encoding=\"UTF-8\"?><diff xmlns:fhir=\"http://hl7.org/fhir\"><replace sel=\"fhir:Patient/fhir:active/@value\">false</replace></diff>";
-		//@formatter:on
-		
-		Patient dest = XmlPatchUtils.apply(ourCtx, p, patchBody);
-		assertEquals(false, dest.getActive());
-	}
-	
-}

hapi-fhir-structures-r4/src/test/java/ca/uhn/fhir/rest/client/CapturingInterceptorTest.java

@@ -5,29 +5,23 @@ 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.*;
-import static org.junit.Assert.assertNull;
-import static org.junit.Assert.assertThat;
 import static org.mockito.Mockito.*;
 
 
@@ -36,6 +30,25 @@ public class CapturingInterceptorTest {
 	@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);
+
+		CapturingInterceptor interceptor = new CapturingInterceptor();
+		interceptor.interceptResponse(expectedResponse);
+		interceptor.interceptRequest(expectedRequest);
+
+		assertEquals(expectedRequest, interceptor.getLastRequest());
+		assertEquals(expectedResponse, interceptor.getLastResponse());
+
+		interceptor.clear();
+
+		assertNull(interceptor.getLastRequest());
+		assertNull(interceptor.getLastResponse());
+	}
 
 	@Test
 	public void testRequest() {
@@ -60,24 +73,11 @@ public class CapturingInterceptorTest {
 	}
 
 	@Test
-    public void testResponseException() throws Exception {
+	public void testResponseBufferApache() throws Exception {
-        IHttpResponse response = mock(IHttpResponse.class);
+		StopWatch responseStopWatch = new StopWatch();
-        IOException expectedCause = new IOException();
-        doThrow(expectedCause).when(response).bufferEntity();
-
-        thrown.expect(InternalErrorException.class);
-        thrown.expectMessage("Unable to buffer the entity for capturing");
-        thrown.expectCause(equalTo(expectedCause));
-
-        CapturingInterceptor interceptor = new CapturingInterceptor();
-        interceptor.interceptResponse(response);
-    }
-
-    @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));
+		IHttpResponse expectedResponse = spy(new ApacheHttpResponse(response, responseStopWatch));
 
 		CapturingInterceptor interceptor = new CapturingInterceptor();
 		interceptor.interceptResponse(expectedResponse);
@@ -91,24 +91,6 @@ public class CapturingInterceptorTest {
 		IOUtils.toString(actualResponse.createReader());
 	}
 
-    @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));
-
-        CapturingInterceptor interceptor = new CapturingInterceptor();
-        interceptor.interceptResponse(expectedResponse);
-        IHttpResponse actualResponse = interceptor.getLastResponse();
-
-        assertEquals(expectedResponse, actualResponse);
-        assertThat("Some content", equalTo(IOUtils.toString(actualResponse.createReader())));
-        verify(expectedResponse, times(0)).bufferEntity();
-
-        //A second call should not throw an exception (StringEntity is repeatable)
-        IOUtils.toString(actualResponse.createReader());
-    }
-
 	@Test
 	public void testResponseBufferOther() throws Exception {
 		Object response = mock(Object.class);
@@ -125,23 +107,36 @@ public class CapturingInterceptorTest {
 	}
 
 	@Test
-    public void testClear(){
+	public void testResponseException() throws Exception {
-        IHttpRequest expectedRequest = mock(IHttpRequest.class);
+		IHttpResponse response = mock(IHttpResponse.class);
-        IHttpResponse expectedResponse = mock(IHttpResponse.class);
+		IOException expectedCause = new IOException();
-        Object response = mock(Object.class);
+		doThrow(expectedCause).when(response).bufferEntity();
-        when(expectedResponse.getResponse()).thenReturn(response);
+
+		thrown.expect(InternalErrorException.class);
+		thrown.expectMessage("Unable to buffer the entity for capturing");
+		thrown.expectCause(equalTo(expectedCause));
+
+		CapturingInterceptor interceptor = new CapturingInterceptor();
+		interceptor.interceptResponse(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);
+		IHttpResponse actualResponse = interceptor.getLastResponse();
 
-        assertEquals(expectedRequest, interceptor.getLastRequest());
+		assertEquals(expectedResponse, actualResponse);
-        assertEquals(expectedResponse, interceptor.getLastResponse());
+		assertThat("Some content", equalTo(IOUtils.toString(actualResponse.createReader())));
+		verify(expectedResponse, times(0)).bufferEntity();
 
-        interceptor.clear();
+		//A second call should not throw an exception (StringEntity is repeatable)
-
+		IOUtils.toString(actualResponse.createReader());
-        assertNull(interceptor.getLastRequest());
-        assertNull(interceptor.getLastResponse());
 	}
 
 }

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);

src/changes/changes.xml

@@ -156,7 +156,9 @@
 			</action>
 			<action type="remove">
 				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.
 			</action>
 			<action type="fix" issue="863">
 				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!
 			</action>
+			<action type="add">
+				The client LoggingInterceptor now includes the number of
+				milliseconds spent performing each call that is logged.
+			</action>
 		</release>
 		<release version="3.2.0" date="2018-01-13">
 			<action type="add">