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

Fix up some logging

This commit is contained in:
James Agnew 2018-03-20 07:53:21 -04:00
parent 4ef07d27aa
commit 9c5e32d7eb
5 changed files with 151 additions and 28 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

106
hapi-fhir-base/src/main/java/ca/uhn/fhir/util/StopWatch.java
View File

@ -6,8 +6,11 @@ import org.apache.commons.lang3.time.DateUtils;
import java.text.DecimalFormat;
import java.text.NumberFormat;
import java.util.Date;
import java.util.LinkedHashMap;
import java.util.concurrent.TimeUnit;
import static org.apache.commons.lang3.StringUtils.isNotBlank;
/*
* #%L
* HAPI FHIR - Core Library
@ -17,9 +20,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.
@ -29,6 +32,14 @@ import java.util.concurrent.TimeUnit;
*/
/**
* A multipurpose stopwatch which can be used to time tasks and produce
* human readable output about task duration, throughput, estimated task completion,
* etc.
* <p>
* <p>
* <b>Thread Safety Note: </b> StopWatch is not intended to be thread safe.
* </p>
*
* @since HAPI FHIR 3.3.0
*/
public class StopWatch {
@ -37,6 +48,9 @@ public class StopWatch {
private static final NumberFormat TEN_DAY_FORMAT = new DecimalFormat("0");
private static Long ourNowForUnitTest;
private long myStarted = now();
private long myCurrentTaskStarted = -1L;
private LinkedHashMap<String, Long> myTaskTotals;
private String myCurrentTaskName;
/**
* Constructor
@ -54,6 +68,66 @@ public class StopWatch {
myStarted = theStart.getTime();
}
private void ensureTaskTotalsMapExists() {
if (myTaskTotals == null) {
myTaskTotals = new LinkedHashMap<>();
}
}
/**
* Finish the counter on the current task (which was started by calling
* {@link #startTask(String)}. This method has no effect if no task
* is currently started so it's ok to call it more than once.
*/
public void endCurrentTask() {
if (isNotBlank(myCurrentTaskName)) {
ensureTaskTotalsMapExists();
Long existingTotal = myTaskTotals.get(myCurrentTaskName);
long taskTimeElapsed = now() - myCurrentTaskStarted;
Long newTotal = existingTotal != null ? existingTotal + taskTimeElapsed : taskTimeElapsed;
myTaskTotals.put(myCurrentTaskName, newTotal);
}
myCurrentTaskName = null;
}
/**
* Returns a string providing the durations of all tasks collected by {@link #startTask(String)}
*/
public String formatTaskDurations() {
// Flush the current task if it's ongoing
String continueTask = myCurrentTaskName;
if (isNotBlank(myCurrentTaskName)) {
endCurrentTask();
startTask(continueTask);
}
ensureTaskTotalsMapExists();
StringBuilder b = new StringBuilder();
for (String nextTask : myTaskTotals.keySet()) {
if (b.length() > 0) {
b.append("\n");
}
b.append(nextTask);
b.append(": ");
b.append(formatMillis(myTaskTotals.get(nextTask)));
}
return b.toString();
}
/**
* Determine the current throughput per unit of time (specified in theUnit)
* assuming that theNumOperations operations have happened.
* <p>
* For example, if this stopwatch has 2 seconds elapsed, and this method is
* called for theNumOperations=30 and TimeUnit=SECONDS,
* this method will return 15
* </p>
*
* @see #getThroughput(int, TimeUnit)
*/
public String formatThroughput(int theNumOperations, TimeUnit theUnit) {
double throughput = getThroughput(theNumOperations, theUnit);
return new DecimalFormat("0.0").format(throughput);
@ -99,6 +173,17 @@ public class StopWatch {
return new Date(myStarted);
}
/**
* Determine the current throughput per unit of time (specified in theUnit)
* assuming that theNumOperations operations have happened.
* <p>
* For example, if this stopwatch has 2 seconds elapsed, and this method is
* called for theNumOperations=30 and TimeUnit=SECONDS,
* this method will return 15
* </p>
*
* @see #formatThroughput(int, TimeUnit)
*/
public double getThroughput(int theNumOperations, TimeUnit theUnit) {
if (theNumOperations <= 0) {
return 0.0f;
@ -117,6 +202,23 @@ public class StopWatch {
myStarted = now();
}
/**
* Starts a counter for a sub-task
* <p>
* <b>Thread Safety Note: </b> This method is not threadsafe! Do not use subtasks in a
* multithreaded environment.
* </p>
*
* @param theTaskName Note that if theTaskName is blank or empty, no task is started
*/
public void startTask(String theTaskName) {
endCurrentTask();
if (isNotBlank(theTaskName)) {
myCurrentTaskStarted = now();
}
myCurrentTaskName = theTaskName;
}
/**
* Formats value in an appropriate format. See {@link #formatMillis(long)}}
* for a description of the format

25
hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java
View File

@ -103,17 +103,32 @@ public class StopWatchTest {
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).replace(',','.'));
assertEquals("2.0 days", StopWatch.formatMillis(DateUtils.MILLIS_PER_DAY * 2).replace(',','.'));
assertEquals("2.0 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 2) + 1).replace(',','.'));
assertEquals("2.4 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 2) + (10 * DateUtils.MILLIS_PER_HOUR)).replace(',','.'));
assertEquals("1.0 day", StopWatch.formatMillis(DateUtils.MILLIS_PER_DAY).replace(',', '.'));
assertEquals("2.0 days", StopWatch.formatMillis(DateUtils.MILLIS_PER_DAY * 2).replace(',', '.'));
assertEquals("2.0 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 2) + 1).replace(',', '.'));
assertEquals("2.4 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 2) + (10 * DateUtils.MILLIS_PER_HOUR)).replace(',', '.'));
assertEquals("11 days", StopWatch.formatMillis((DateUtils.MILLIS_PER_DAY * 11) + (10 * DateUtils.MILLIS_PER_HOUR)));
}
@Test
public void testFormatTaskDurations() {
StopWatch sw = new StopWatch();
StopWatch.setNowForUnitTestForUnitTest(1000L);
sw.startTask("TASK1");
StopWatch.setNowForUnitTestForUnitTest(1500L);
sw.startTask("TASK2");
StopWatch.setNowForUnitTestForUnitTest(1600L);
String taskDurations = sw.formatTaskDurations();
assertEquals("TASK1: 500ms\nTASK2: 100ms", taskDurations);
}
@Test
public void testFormatThroughput60Ops4Min() {
StopWatch sw = new StopWatch(DateUtils.addMinutes(new Date(), -4));
String throughput = sw.formatThroughput(60, TimeUnit.MINUTES).replace(',','.');
String throughput = sw.formatThroughput(60, TimeUnit.MINUTES).replace(',', '.');
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"));
}

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

@ -32,8 +32,6 @@ import ca.uhn.fhir.util.StopWatch;
import ca.uhn.fhir.rest.param.ParameterUtil;
import org.apache.commons.lang3.Validate;
import org.apache.http.NameValuePair;
import org.hibernate.Session;
import org.hibernate.internal.SessionImpl;
import org.hl7.fhir.dstu3.model.*;
import org.hl7.fhir.dstu3.model.Bundle.*;
import org.hl7.fhir.dstu3.model.OperationOutcome.IssueSeverity;
@ -150,7 +148,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
if (transactionType == null) {
String message = "Transactiion Bundle did not specify valid Bundle.type, assuming " + BundleType.TRANSACTION.toCode();
String message = "Transaction Bundle did not specify valid Bundle.type, assuming " + BundleType.TRANSACTION.toCode();
ourLog.warn(message);
transactionType = BundleType.TRANSACTION;
}
@ -158,9 +156,10 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
throw new InvalidRequestException("Unable to process transaction where incoming Bundle.type = " + transactionType.toCode());
}
ourLog.info("Beginning {} with {} resources", theActionName, theRequest.getEntry().size());
ourLog.debug("Beginning {} with {} resources", theActionName, theRequest.getEntry().size());
long start = System.currentTimeMillis();
// long start = System.currentTimeMillis();
final StopWatch transactionSw = new StopWatch();
final Date updateTime = new Date();
final Set<IdType> allIds = new LinkedHashSet<IdType>();
@ -202,7 +201,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
* Basically if the resource has a match URL that references a placeholder,
* we try to handle the resource with the placeholder first.
*/
Set<String> placeholderIds = new HashSet<String>();
Set<String> placeholderIds = new HashSet<>();
final List<BundleEntryComponent> entries = theRequest.getEntry();
for (BundleEntryComponent nextEntry : entries) {
if (isNotBlank(nextEntry.getFullUrl()) && nextEntry.getFullUrl().startsWith(IdType.URN_PREFIX)) {
@ -224,7 +223,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
Map<BundleEntryComponent, ResourceTable> entriesToProcess = txManager.execute(new TransactionCallback<Map<BundleEntryComponent, ResourceTable>>() {
@Override
public Map<BundleEntryComponent, ResourceTable> doInTransaction(TransactionStatus status) {
return doTransactionWriteOperations(theRequestDetails, theRequest, theActionName, updateTime, allIds, idSubstitutions, idToPersistedOutcome, response, originalRequestOrder, entries);
return doTransactionWriteOperations(theRequestDetails, theRequest, theActionName, updateTime, allIds, idSubstitutions, idToPersistedOutcome, response, originalRequestOrder, entries, transactionSw);
}
});
for (Entry<BundleEntryComponent, ResourceTable> nextEntry : entriesToProcess.entrySet()) {
@ -237,8 +236,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
/*
* Loop through the request and process any entries of type GET
*/
for (int i = 0; i < getEntries.size(); i++) {
BundleEntryComponent nextReqEntry = getEntries.get(i);
for (BundleEntryComponent nextReqEntry : getEntries) {
Integer originalOrder = originalRequestOrder.get(nextReqEntry);
BundleEntryComponent nextRespEntry = response.getEntry().get(originalOrder);
@ -258,7 +256,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
for (NameValuePair next : parameters) {
paramValues.put(next.getName(), next.getValue());
}
for (java.util.Map.Entry<String, Collection<String>> nextParamEntry : paramValues.asMap().entrySet()) {
for (Entry<String, Collection<String>> nextParamEntry : paramValues.asMap().entrySet()) {
String[] nextValue = nextParamEntry.getValue().toArray(new String[nextParamEntry.getValue().size()]);
requestDetails.addParameter(nextParamEntry.getKey(), nextValue);
}
@ -302,8 +300,8 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
long delay = System.currentTimeMillis() - start;
ourLog.info(theActionName + " completed in {}ms", new Object[] { delay });
ourLog.info(theActionName + " completed in {}", transactionSw.toString());
ourLog.info(theActionName + " details:\n{}", transactionSw.formatTaskDurations());
response.setType(BundleType.TRANSACTIONRESPONSE);
return response;
@ -311,12 +309,12 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
@SuppressWarnings("unchecked")
private Map<BundleEntryComponent, ResourceTable> doTransactionWriteOperations(ServletRequestDetails theRequestDetails, Bundle theRequest, String theActionName, Date updateTime, Set<IdType> allIds,
Map<IdType, IdType> theIdSubstitutions, Map<IdType, DaoMethodOutcome> idToPersistedOutcome, Bundle response, IdentityHashMap<BundleEntryComponent, Integer> originalRequestOrder, List<BundleEntryComponent> theEntries) {
Set<String> deletedResources = new HashSet<String>();
List<DeleteConflict> deleteConflicts = new ArrayList<DeleteConflict>();
Map<BundleEntryComponent, ResourceTable> entriesToProcess = new IdentityHashMap<BundleEntryComponent, ResourceTable>();
Set<ResourceTable> nonUpdatedEntities = new HashSet<ResourceTable>();
Map<String, Class<? extends IBaseResource>> conditionalRequestUrls = new HashMap<String, Class<? extends IBaseResource>>();
Map<IdType, IdType> theIdSubstitutions, Map<IdType, DaoMethodOutcome> idToPersistedOutcome, Bundle response, IdentityHashMap<BundleEntryComponent, Integer> originalRequestOrder, List<BundleEntryComponent> theEntries, StopWatch theStopWatch) {
Set<String> deletedResources = new HashSet<>();
List<DeleteConflict> deleteConflicts = new ArrayList<>();
Map<BundleEntryComponent, ResourceTable> entriesToProcess = new IdentityHashMap<>();
Set<ResourceTable> nonUpdatedEntities = new HashSet<>();
Map<String, Class<? extends IBaseResource>> conditionalRequestUrls = new HashMap<>();
/*
* Loop through the request and process any entries of type
@ -371,6 +369,8 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
String resourceType = res != null ? getContext().getResourceDefinition(res).getName() : null;
BundleEntryComponent nextRespEntry = response.getEntry().get(originalRequestOrder.get(nextReqEntry));
theStopWatch.startTask("Process entry " + i + ": " + verb + " " + defaultString(resourceType));
switch (verb) {
case POST: {
// CREATE
@ -470,6 +470,8 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
}
theStopWatch.endCurrentTask();
/*
* Make sure that there are no conflicts from deletions. E.g. we can't delete something
* if something else has a reference to it.. Unless the thing that has a reference to it
@ -538,8 +540,12 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
}
theStopWatch.startTask("Flush Session");
flushJpaSession();
theStopWatch.endCurrentTask();
/*
* Double check we didn't allow any duplicates we shouldn't have
*/

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

@ -157,7 +157,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao<Bundle, Meta> {
}
if (transactionType == null) {
String message = "Transactiion Bundle did not specify valid Bundle.type, assuming " + BundleType.TRANSACTION.toCode();
String message = "Transaction Bundle did not specify valid Bundle.type, assuming " + BundleType.TRANSACTION.toCode();
ourLog.warn(message);
transactionType = BundleType.TRANSACTION;
}
@ -165,7 +165,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao<Bundle, Meta> {
throw new InvalidRequestException("Unable to process transaction where incoming Bundle.type = " + transactionType.toCode());
}
ourLog.info("Beginning {} with {} resources", theActionName, theRequest.getEntry().size());
ourLog.debug("Beginning {} with {} resources", theActionName, theRequest.getEntry().size());
long start = System.currentTimeMillis();
final Date updateTime = new Date();

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

@ -49,7 +49,7 @@ public abstract class BaseSubscriptionDeliverySubscriber extends BaseSubscriptio
try {
ResourceDeliveryMessage msg = (ResourceDeliveryMessage) theMessage.getPayload();
subscriptionId = msg.getPayload(getContext()).getIdElement().getValue();
subscriptionId = msg.getSubscription().getIdElement(getContext()).getValue();
if (!subscriptionTypeApplies(getContext(), msg.getSubscription().getBackingSubscription(getContext()))) {
return;