honeymoose
/
hapi-fhir
mirror of https://github.com/hapifhir/hapi-fhir.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Logging enhancements

This commit is contained in:
James Agnew 2018-03-04 10:21:39 -05:00
parent 0c0b9bd74b
commit 928cf23b4c
7 changed files with 197 additions and 116 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -65,31 +65,31 @@ public interface IHttpResponse {
/**
* Close the response
*/
public void close();
void close();
/**
* Returna reader for the response entity
*/
public Reader createReader() throws IOException;
Reader createReader() throws IOException;
/**
* Get map of the response headers and corresponding string values.
*
* @return response headers as a map header keys and they values.
*/
public Map<String, List<String>> getAllHeaders();
Map<String, List<String>> getAllHeaders();
/**
* Return all headers in the response with the given type
*/
public List<String> getHeaders(String theName);
List<String> getHeaders(String theName);
/**
* Extracts {@code Content-Type} value from the response exactly as
* specified by the {@code Content-Type} header. Returns {@code null}
* if not specified.
*/
public String getMimeType();
String getMimeType();
/**
* @return the native response, depending on the client library used
@ -101,18 +101,18 @@ public interface IHttpResponse {
*
* @return the response status code.
*/
public int getStatus();
int getStatus();
/**
* Get the response status information reason phrase associated with the response.
*
* @return the reason phrase.
*/
public String getStatusInfo();
String getStatusInfo();
/**
* Read the message entity input stream as an InputStream.
*/
public InputStream readEntity() throws IOException;
InputStream readEntity() throws IOException;
}

6
hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/FhirSystemDaoDstu2.java
View File

@ -463,7 +463,7 @@ public class FhirSystemDaoDstu2 extends BaseHapiFhirSystemDao<Bundle, MetaDt> {
}
if (idSubstitutions.containsKey(nextId)) {
IdDt newId = idSubstitutions.get(nextId);
ourLog.info(" * Replacing resource ref {} with {}", nextId, newId);
ourLog.debug(" * Replacing resource ref {} with {}", nextId, newId);
nextRef.setReference(newId);
} else {
ourLog.debug(" * Reference [{}] does not exist in bundle", nextId);
@ -479,7 +479,7 @@ public class FhirSystemDaoDstu2 extends BaseHapiFhirSystemDao<Bundle, MetaDt> {
IdDt nextUriString = new IdDt(nextRef.getValueAsString());
if (idSubstitutions.containsKey(nextUriString)) {
IdDt newId = idSubstitutions.get(nextUriString);
ourLog.info(" * Replacing resource ref {} with {}", nextUriString, newId);
ourLog.debug(" * Replacing resource ref {} with {}", nextUriString, newId);
nextRef.setValue(newId.getValue());
} else {
ourLog.debug(" * Reference [{}] does not exist in bundle", nextUriString);
@ -522,7 +522,7 @@ public class FhirSystemDaoDstu2 extends BaseHapiFhirSystemDao<Bundle, MetaDt> {
if (replacement.equals(next)) {
continue;
}
ourLog.info("Placeholder resource ID \"{}\" was replaced with permanent ID \"{}\"", next, replacement);
ourLog.debug("Placeholder resource ID \"{}\" was replaced with permanent ID \"{}\"", next, replacement);
}
/*

8
hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/dstu3/FhirSystemDaoDstu3.java
View File

@ -505,7 +505,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
if (theIdSubstitutions.containsKey(nextId)) {
IdType newId = theIdSubstitutions.get(nextId);
ourLog.info(" * Replacing resource ref {} with {}", nextId, newId);
ourLog.debug(" * Replacing resource ref {} with {}", nextId, newId);
nextRef.setReference(newId.getValue());
} else if (nextId.getValue().startsWith("urn:")) {
throw new InvalidRequestException("Unable to satisfy placeholder ID: " + nextId.getValue());
@ -523,7 +523,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
IdType nextUriString = new IdType(nextRef.getValueAsString());
if (theIdSubstitutions.containsKey(nextUriString)) {
IdType newId = theIdSubstitutions.get(nextUriString);
ourLog.info(" * Replacing resource ref {} with {}", nextUriString, newId);
ourLog.debug(" * Replacing resource ref {} with {}", nextUriString, newId);
nextRef.setValue(newId.getValue());
} else {
ourLog.debug(" * Reference [{}] does not exist in bundle", nextUriString);
@ -544,7 +544,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
StopWatch sw = new StopWatch();
myEntityManager.flush();
ourLog.info("Session flush took {}ms for {} inserts and {} updates", sw.getMillis(), insertionCount, updateCount);
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
@ -570,7 +570,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
if (replacement.equals(next)) {
continue;
}
ourLog.info("Placeholder resource ID \"{}\" was replaced with permanent ID \"{}\"", next, replacement);
ourLog.debug("Placeholder resource ID \"{}\" was replaced with permanent ID \"{}\"", next, replacement);
}
return entriesToProcess;
}

7
hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/dao/r4/FhirSystemDaoR4.java
View File

@ -514,7 +514,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
if (theIdSubstitutions.containsKey(nextId)) {
IdType newId = theIdSubstitutions.get(nextId);
ourLog.info(" * Replacing resource ref {} with {}", nextId, newId);
ourLog.debug(" * Replacing resource ref {} with {}", nextId, newId);
nextRef.setReference(newId.getValue());
} else if (nextId.getValue().startsWith("urn:")) {
throw new InvalidRequestException("Unable to satisfy placeholder ID: " + nextId.getValue());
@ -532,7 +532,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao<Bundle, Meta> {
IdType nextUriString = new IdType(nextRef.getValueAsString());
if (theIdSubstitutions.containsKey(nextUriString)) {
IdType newId = theIdSubstitutions.get(nextUriString);
ourLog.info(" * Replacing resource ref {} with {}", nextUriString, newId);
ourLog.debug(" * Replacing resource ref {} with {}", nextUriString, newId);
nextRef.setValue(newId.getValue());
} else {
ourLog.debug(" * Reference [{}] does not exist in bundle", nextUriString);
@ -548,6 +548,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
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
@ -573,7 +574,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao<Bundle, Meta> {
if (replacement.equals(next)) {
continue;
}
ourLog.info("Placeholder resource ID \"{}\" was replaced with permanent ID \"{}\"", next, replacement);
ourLog.debug("Placeholder resource ID \"{}\" was replaced with permanent ID \"{}\"", next, replacement);
}
return entriesToProcess;
}

10
hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionDeliverySubscriber.java
View File

@ -44,8 +44,13 @@ public abstract class BaseSubscriptionDeliverySubscriber extends BaseSubscriptio
ourLog.warn("Unexpected payload type: {}", theMessage.getPayload());
return;
}
String subscriptionId = "(unknown?)";
try {
ResourceDeliveryMessage msg = (ResourceDeliveryMessage) theMessage.getPayload();
subscriptionId = msg.getPayload(getContext()).getIdElement().getValue();
if (!subscriptionTypeApplies(getContext(), msg.getSubscription().getBackingSubscription(getContext()))) {
return;
}
@ -77,8 +82,9 @@ public abstract class BaseSubscriptionDeliverySubscriber extends BaseSubscriptio
handleMessage(msg);
} catch (Exception e) {
ourLog.error("Failure handling subscription payload", e);
throw new MessagingException(theMessage, "Failure handling subscription payload", e);
String msg = "Failure handling subscription payload for subscription: " + subscriptionId;
ourLog.error(msg, e);
throw new MessagingException(theMessage, msg, e);
}
}

90
hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java
View File

@ -1,8 +1,10 @@
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;
@ -15,9 +17,9 @@ import java.util.concurrent.TimeUnit;
* 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.
@ -28,7 +30,10 @@ import java.util.concurrent.TimeUnit;
public class StopWatch {
private long myStarted = System.currentTimeMillis();
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
@ -46,17 +51,42 @@ public class StopWatch {
myStarted = theStart.getTime();
}
public long getMillis() {
long now = System.currentTimeMillis();
return now - myStarted;
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 = System.currentTimeMillis();
long now = now();
long retVal = now - myStarted;
myStarted = now;
return retVal;
@ -82,18 +112,13 @@ public class StopWatch {
long periodMillis = theUnit.toMillis(1);
double numerator = theNumOperations;
double denominator = ((double)millisElapsed)/((double)periodMillis);
double denominator = ((double) millisElapsed) / ((double) periodMillis);
return numerator / denominator;
}
public String formatThroughput(int theNumOperations, TimeUnit theUnit) {
double throughput = getThroughput(theNumOperations, theUnit);
return new DecimalFormat("0.0").format(throughput);
}
public void restart() {
myStarted = System.currentTimeMillis();
myStarted = now();
}
/**
@ -124,21 +149,38 @@ public class StopWatch {
static public String formatMillis(long val) {
StringBuilder buf = new StringBuilder(20);
if (val >= DateUtils.MILLIS_PER_DAY) {
long days = val / DateUtils.MILLIS_PER_DAY;
append(buf, "", 1, days);
if (days > 1) {
buf.append(" days ");
} else if (days == 1) {
buf.append(" 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");
}
append(buf, "", 2, ((val % DateUtils.MILLIS_PER_DAY) / DateUtils.MILLIS_PER_HOUR));
} 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));
}
}
append(buf, ":", 2, ((val % DateUtils.MILLIS_PER_HOUR) / DateUtils.MILLIS_PER_MINUTE));
append(buf, ":", 2, ((val % DateUtils.MILLIS_PER_MINUTE) / DateUtils.MILLIS_PER_SECOND));
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;
}
}

176
hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java
View File

@ -1,20 +1,118 @@
package ca.uhn.fhir.jpa.util;
import static org.hamcrest.Matchers.*;
import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertThat;
import org.apache.commons.lang3.time.DateUtils;
import org.hamcrest.Matchers;
import org.junit.After;
import org.junit.Test;
import java.util.Date;
import java.util.concurrent.TimeUnit;
import org.apache.commons.lang3.time.DateUtils;
import org.hamcrest.Matchers;
import org.junit.Test;
import static org.hamcrest.Matchers.*;
import static org.junit.Assert.*;
public class StopWatchTest {
private static final org.slf4j.Logger ourLog = org.slf4j.LoggerFactory.getLogger(StopWatchTest.class);
@After
public void after() {
StopWatch.setNowForUnitTestForUnitTest(null);
}
private double calculateThroughput(int theMinutesElapsed, int theNumOperations) {
StopWatch sw = new StopWatch(DateUtils.addMinutes(new Date(), -theMinutesElapsed));
double throughput = sw.getThroughput(theNumOperations, TimeUnit.MINUTES);
ourLog.info("{} operations in {}ms = {} ops / second", theNumOperations, sw.getMillis(), throughput);
return throughput;
}
@Test
public void testEstimatedTimeRemaining() {
StopWatch.setNowForUnitTestForUnitTest(777777777L);
StopWatch sw = new StopWatch();
StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE);
assertEquals("00:00:00.600", sw.getEstimatedTimeRemaining(0.99, 1.0));
StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE);
assertEquals("00:10:00", sw.getEstimatedTimeRemaining(0.1, 1.0));
StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE + 100);
assertEquals("00:10:01", sw.getEstimatedTimeRemaining(0.1, 1.0));
StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE);
assertEquals("00:20:00", sw.getEstimatedTimeRemaining(0.05, 1.0));
StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE);
assertEquals("00:40:00", sw.getEstimatedTimeRemaining(0.025, 1.0));
StopWatch.setNowForUnitTestForUnitTest(777777777L + DateUtils.MILLIS_PER_MINUTE);
assertEquals("01:40:00", sw.getEstimatedTimeRemaining(0.01, 1.0));
}
@Test
public void testFormatMillis() {
assertEquals("00:00:01.000", 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));
assertEquals("1.0 day", StopWatch.formatMillis(DateUtils.MILLIS_PER_DAY));
assertEquals("2.0 days", StopWatch.formatMillis(DateUtils.MILLIS_PER_DAY * 2));
assertEquals("2.0 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 2) + 1));
assertEquals("2.4 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 2) + (10 * DateUtils.MILLIS_PER_HOUR)));
assertEquals("11 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 11) + (10 * DateUtils.MILLIS_PER_HOUR)));
}
@Test
public void testFormatThroughput60Ops4Min() {
StopWatch sw = new StopWatch(DateUtils.addMinutes(new Date(), -4));
String throughput = sw.formatThroughput(60, TimeUnit.MINUTES);
ourLog.info("{} operations in {}ms = {} ops / second", 60, sw.getMillis(), throughput);
assertThat(throughput, oneOf("14.9", "15.0", "15.1", "14,9", "15,0", "15,1"));
}
@Test
public void testMillisPerOperation() {
int minutes = 60;
StopWatch sw = new StopWatch(DateUtils.addMinutes(new Date(), -minutes));
int numOperations = 60;
int millis = sw.getMillisPerOperation(numOperations);
ourLog.info("{} operations in {}ms = {}ms / operation", numOperations, minutes * DateUtils.MILLIS_PER_MINUTE, millis);
assertThat(millis, Matchers.lessThan(62000));
assertThat(millis, Matchers.greaterThan(58000));
}
@Test
public void testOperationThroughput30Ops1Min() {
double throughput = calculateThroughput(1, 30);
assertThat(throughput, greaterThan(29.0));
assertThat(throughput, lessThan(31.0));
}
@Test
public void testOperationThroughput60Ops1Min() {
double throughput = calculateThroughput(1, 60);
assertThat(throughput, greaterThan(59.0));
assertThat(throughput, lessThan(61.0));
}
@Test
public void testOperationThroughput60Ops4Min() {
double throughput = calculateThroughput(4, 60);
assertThat(throughput, greaterThan(14.0));
assertThat(throughput, lessThan(16.0));
}
@Test
public void testRestart() throws InterruptedException {
StopWatch sw = new StopWatch();
Thread.sleep(500);
sw.restart();
assertThat(sw.getMillis(), lessThan(100L));
}
@Test
public void testStopwatch() throws Exception {
StopWatch sw = new StopWatch();
@ -37,62 +135,6 @@ public class StopWatchTest {
assertThat(sw.getStartedDate().getTime(), lessThan(System.currentTimeMillis()));
}
@Test
public void testRestart() throws InterruptedException {
StopWatch sw = new StopWatch();
Thread.sleep(500);
sw.restart();
assertThat(sw.getMillis(), lessThan(100L));
}
@Test
public void testMillisPerOperation() {
int minutes = 60;
StopWatch sw = new StopWatch(DateUtils.addMinutes(new Date(), -minutes));
int numOperations = 60;
int millis = sw.getMillisPerOperation(numOperations);
ourLog.info("{} operations in {}ms = {}ms / operation", numOperations, minutes*DateUtils.MILLIS_PER_MINUTE, millis);
assertThat(millis, Matchers.lessThan(62000));
assertThat(millis, Matchers.greaterThan(58000));
}
@Test
public void testOperationThroughput60Ops1Min() {
double throughput = calculateThroughput(1, 60);
assertThat(throughput, greaterThan(59.0));
assertThat(throughput, lessThan(61.0));
}
@Test
public void testOperationThroughput30Ops1Min() {
double throughput = calculateThroughput(1, 30);
assertThat(throughput, greaterThan(29.0));
assertThat(throughput, lessThan(31.0));
}
@Test
public void testOperationThroughput60Ops4Min() {
double throughput = calculateThroughput(4, 60);
assertThat(throughput, greaterThan(14.0));
assertThat(throughput, lessThan(16.0));
}
@Test
public void testFormatThroughput60Ops4Min() {
StopWatch sw = new StopWatch(DateUtils.addMinutes(new Date(), -4));
String throughput = sw.formatThroughput(60, TimeUnit.MINUTES);
ourLog.info("{} operations in {}ms = {} ops / second", 60, sw.getMillis(), throughput);
assertThat(throughput, oneOf("14.9", "15.0", "15.1", "14,9", "15,0", "15,1"));
}
private double calculateThroughput(int theMinutesElapsed, int theNumOperations) {
StopWatch sw = new StopWatch(DateUtils.addMinutes(new Date(), -theMinutesElapsed));
double throughput = sw.getThroughput(theNumOperations, TimeUnit.MINUTES);
ourLog.info("{} operations in {}ms = {} ops / second", theNumOperations, sw.getMillis(), throughput);
return throughput;
}
@Test
public void testToString() throws Exception {
StopWatch sw = new StopWatch();
@ -104,14 +146,4 @@ public class StopWatchTest {
assertThat(string, startsWith("00:00"));
}
@Test
public void testFormatMillis() throws Exception {
assertEquals("00:00:01.000", StopWatch.formatMillis(DateUtils.MILLIS_PER_SECOND));
assertEquals("00:01:00.000", StopWatch.formatMillis(DateUtils.MILLIS_PER_MINUTE));
assertEquals("01:00:00.000", StopWatch.formatMillis(DateUtils.MILLIS_PER_HOUR));
assertEquals("1 day 00:00:00.000", StopWatch.formatMillis(DateUtils.MILLIS_PER_DAY));
assertEquals("2 days 00:00:00.000", StopWatch.formatMillis(DateUtils.MILLIS_PER_DAY*2));
assertEquals("2 days 00:00:00.001", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY*2)+1));
}
}