diff --git a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java index 8928ffa8fe6..c77a5bc702a 100644 --- a/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java +++ b/hapi-fhir-jpaserver-base/src/main/java/ca/uhn/fhir/jpa/util/StopWatch.java @@ -2,7 +2,9 @@ package ca.uhn.fhir.jpa.util; import org.apache.commons.lang3.time.DateUtils; +import java.text.DecimalFormat; import java.util.Date; +import java.util.concurrent.TimeUnit; /* * #%L @@ -13,9 +15,9 @@ import java.util.Date; * 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. @@ -37,9 +39,20 @@ public class StopWatch { /** * Constructor + * + * @param theStart The time to record as the start for this timer */ - public StopWatch(Date theNow) { - myStarted = theNow.getTime(); + public StopWatch(Date theStart) { + myStarted = theStart.getTime(); + } + + public long getMillis() { + long now = System.currentTimeMillis(); + return now - myStarted; + } + + public long getMillis(Date theNow) { + return theNow.getTime() - myStarted; } public long getMillisAndRestart() { @@ -49,21 +62,40 @@ public class StopWatch { return retVal; } - public long getMillis() { - long now = System.currentTimeMillis(); - long retVal = now - myStarted; - return retVal; - } - - public long getMillis(Date theNow) { - long retVal = theNow.getTime() - myStarted; - 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 String formatThroughput(int theNumOperations, TimeUnit theUnit) { + double throughput = getThroughput(theNumOperations, theUnit); + return new DecimalFormat("0.0").format(throughput); + } + + public void restart() { + myStarted = System.currentTimeMillis(); + } + /** * Formats value in the format [DD d ]HH:mm:ss.SSSS */ @@ -72,6 +104,23 @@ public class StopWatch { 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) { @@ -92,27 +141,4 @@ public class StopWatch { return buf.toString(); } - /** 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); - } - - /** - * @param theNumOperations Ok for this to be 0, it will be treated as 1 - */ - public int getMillisPerOperation(int theNumOperations) { - int numOperations = Math.min(1, theNumOperations); - return (int)(((double) getMillis()) / Math.max(1.0, numOperations)); - } - } diff --git a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java index 4a88d0422a8..86c4840b9c8 100644 --- a/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java +++ b/hapi-fhir-jpaserver-base/src/test/java/ca/uhn/fhir/jpa/util/StopWatchTest.java @@ -1,14 +1,14 @@ package ca.uhn.fhir.jpa.util; -import static org.hamcrest.Matchers.greaterThan; -import static org.hamcrest.Matchers.lessThan; -import static org.hamcrest.Matchers.startsWith; +import static org.hamcrest.Matchers.*; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertThat; import java.util.Date; +import java.util.concurrent.TimeUnit; import org.apache.commons.lang3.time.DateUtils; +import org.hamcrest.Matchers; import org.junit.Test; public class StopWatchTest { @@ -37,6 +37,62 @@ 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")); + } + + 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();