From 9c5e32d7eb706193bd8dc50f72fc6c8f6746d613 Mon Sep 17 00:00:00 2001 From: James Agnew Date: Tue, 20 Mar 2018 07:53:21 -0400 Subject: [PATCH] Fix up some logging --- .../main/java/ca/uhn/fhir/util/StopWatch.java | 106 +++++++++++++++++- .../java/ca/uhn/fhir/util/StopWatchTest.java | 25 ++++- .../jpa/dao/dstu3/FhirSystemDaoDstu3.java | 42 ++++--- .../uhn/fhir/jpa/dao/r4/FhirSystemDaoR4.java | 4 +- .../BaseSubscriptionDeliverySubscriber.java | 2 +- 5 files changed, 151 insertions(+), 28 deletions(-) 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 index 8103c31c81f..63c9fe115a2 100644 --- 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 @@ -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. + *

+ *

+ * Thread Safety Note: StopWatch is not intended to be thread safe. + *

+ * * @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 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. + *

+ * 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 + *

+ * + * @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. + *

+ * 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 + *

+ * + * @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 + *

+ * Thread Safety Note: This method is not threadsafe! Do not use subtasks in a + * multithreaded environment. + *

+ * + * @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 diff --git a/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java b/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java index d80f624e065..45a854094f5 100644 --- a/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java +++ b/hapi-fhir-base/src/test/java/ca/uhn/fhir/util/StopWatchTest.java @@ -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")); } 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 64ccf5b564d..43dc130ee64 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 @@ -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 { } 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 { 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 allIds = new LinkedHashSet(); @@ -202,7 +201,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao { * Basically if the resource has a match URL that references a placeholder, * we try to handle the resource with the placeholder first. */ - Set placeholderIds = new HashSet(); + Set placeholderIds = new HashSet<>(); final List 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 { Map entriesToProcess = txManager.execute(new TransactionCallback>() { @Override public Map 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 nextEntry : entriesToProcess.entrySet()) { @@ -237,8 +236,7 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao { /* * 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 { for (NameValuePair next : parameters) { paramValues.put(next.getName(), next.getValue()); } - for (java.util.Map.Entry> nextParamEntry : paramValues.asMap().entrySet()) { + for (Entry> 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 { } - 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 { @SuppressWarnings("unchecked") private Map doTransactionWriteOperations(ServletRequestDetails theRequestDetails, Bundle theRequest, String theActionName, Date updateTime, Set allIds, - Map theIdSubstitutions, Map idToPersistedOutcome, Bundle response, IdentityHashMap originalRequestOrder, List theEntries) { - Set deletedResources = new HashSet(); - List deleteConflicts = new ArrayList(); - Map entriesToProcess = new IdentityHashMap(); - Set nonUpdatedEntities = new HashSet(); - Map> conditionalRequestUrls = new HashMap>(); + Map theIdSubstitutions, Map idToPersistedOutcome, Bundle response, IdentityHashMap originalRequestOrder, List theEntries, StopWatch theStopWatch) { + Set deletedResources = new HashSet<>(); + List deleteConflicts = new ArrayList<>(); + Map entriesToProcess = new IdentityHashMap<>(); + Set nonUpdatedEntities = new HashSet<>(); + Map> conditionalRequestUrls = new HashMap<>(); /* * Loop through the request and process any entries of type @@ -371,6 +369,8 @@ public class FhirSystemDaoDstu3 extends BaseHapiFhirSystemDao { 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 { } } + 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 { } } + theStopWatch.startTask("Flush Session"); + flushJpaSession(); + theStopWatch.endCurrentTask(); + /* * 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 f4e2e05f1e4..d32621b087c 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 @@ -157,7 +157,7 @@ public class FhirSystemDaoR4 extends BaseHapiFhirSystemDao { } 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 { 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(); diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionDeliverySubscriber.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionDeliverySubscriber.java index bf6a56a2c16..3b3dfcaf3a7 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionDeliverySubscriber.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/subscription/BaseSubscriptionDeliverySubscriber.java @@ -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;