zzh
/
gatk-3.8
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Done GSA-539: SimpleTimer should use System.nanoTime for nanoSecond resolution

This commit is contained in:
Mark DePristo 2012-09-02 11:37:30 -04:00
parent 59109d5eeb
commit 6a5a70cdf1
2 changed files with 128 additions and 24 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

89
public/java/src/org/broadinstitute/sting/utils/SimpleTimer.java
View File

@ -1,18 +1,42 @@
package org.broadinstitute.sting.utils;
import com.google.java.contract.Ensures;
import com.google.java.contract.Requires;
import java.util.concurrent.TimeUnit;
/**
* A useful simple system for timing code. This code is not thread safe!
* A useful simple system for timing code with nano second resolution
*
* Note that this code is not thread-safe. If you have a single timer
* being started and stopped by multiple threads you will need to protect the
* calls to avoid meaningless results of having multiple starts and stops
* called sequentially.
*
* User: depristo
* Date: Dec 10, 2010
* Time: 9:07:44 AM
*/
public class SimpleTimer {
final private String name;
private long elapsed = 0l;
private long startTime = 0l;
boolean running = false;
protected static final double NANO_TO_SECOND_DOUBLE = 1.0 / TimeUnit.SECONDS.toNanos(1);
private final String name;
/**
* The elapsedTimeNano time in nanoSeconds of this timer. The elapsedTimeNano time is the
* sum of times between starts/restrats and stops.
*/
private long elapsedTimeNano = 0l;
/**
* The start time of the last start/restart in nanoSeconds
*/
private long startTimeNano = 0l;
/**
* Is this timer currently running (i.e., the last call was start/restart)
*/
private boolean running = false;
/**
* Creates an anonymous simple timer
@ -25,7 +49,8 @@ public class SimpleTimer {
* Creates a simple timer named name
* @param name of the timer, must not be null
*/
public SimpleTimer(String name) {
public SimpleTimer(final String name) {
if ( name == null ) throw new IllegalArgumentException("SimpleTimer name cannot be null");
this.name = name;
}
@ -37,27 +62,27 @@ public class SimpleTimer {
}
/**
* Starts the timer running, and sets the elapsed time to 0. This is equivalent to
* Starts the timer running, and sets the elapsedTimeNano time to 0. This is equivalent to
* resetting the time to have no history at all.
*
* @return this object, for programming convenience
*/
@Ensures("elapsedTimeNano == 0l")
public synchronized SimpleTimer start() {
elapsed = 0l;
restart();
return this;
elapsedTimeNano = 0l;
return restart();
}
/**
* Starts the timer running, without reseting the elapsed time. This function may be
* Starts the timer running, without resetting the elapsedTimeNano time. This function may be
* called without first calling start(). The only difference between start and restart
* is that start resets the elapsed time, while restart does not.
* is that start resets the elapsedTimeNano time, while restart does not.
*
* @return this object, for programming convenience
*/
public synchronized SimpleTimer restart() {
running = true;
startTime = currentTime();
startTimeNano = currentTimeNano();
return this;
}
@ -71,29 +96,53 @@ public class SimpleTimer {
/**
* @return A convenience function to obtain the current time in milliseconds from this timer
*/
public synchronized long currentTime() {
public long currentTime() {
return System.currentTimeMillis();
}
/**
* Stops the timer. Increases the elapsed time by difference between start and now. The
* timer must be running in order to call stop
* @return A convenience function to obtain the current time in nanoSeconds from this timer
*/
public long currentTimeNano() {
return System.nanoTime();
}
/**
* Stops the timer. Increases the elapsedTimeNano time by difference between start and now.
*
* It's ok to call stop on a timer that's not running. It has no effect on the timer.
*
* @return this object, for programming convenience
*/
@Requires("startTimeNano != 0l")
public synchronized SimpleTimer stop() {
running = false;
elapsed += currentTime() - startTime;
if ( running ) {
running = false;
elapsedTimeNano += currentTimeNano() - startTimeNano;
}
return this;
}
/**
* Returns the total elapsed time of all start/stops of this timer. If the timer is currently
* Returns the total elapsedTimeNano time of all start/stops of this timer. If the timer is currently
* running, includes the difference from currentTime() and the start as well
*
* @return this time, in seconds
*/
public synchronized double getElapsedTime() {
return (running ? (currentTime() - startTime + elapsed) : elapsed) / 1000.0;
return nanoToSecondsAsDouble(getElapsedTimeNano());
}
protected static double nanoToSecondsAsDouble(final long nano) {
return nano * NANO_TO_SECOND_DOUBLE;
}
/**
* @see #getElapsedTime() but returns the result in nanoseconds
*
* @return the elapsed time in nanoseconds
*/
public synchronized long getElapsedTimeNano() {
return running ? (currentTimeNano() - startTimeNano + elapsedTimeNano) : elapsedTimeNano;
}
}

63
public/java/test/org/broadinstitute/sting/utils/SimpleTimerUnitTest.java
View File

@ -1,12 +1,12 @@
package org.broadinstitute.sting.utils;
import org.broadinstitute.sting.BaseTest;
import org.broadinstitute.sting.utils.exceptions.ReviewedStingException;
import org.testng.Assert;
import org.testng.annotations.BeforeClass;
import org.testng.annotations.Test;
import java.io.File;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.TimeUnit;
public class SimpleTimerUnitTest extends BaseTest {
private final static String NAME = "unit.test.timer";
@ -17,33 +17,88 @@ public class SimpleTimerUnitTest extends BaseTest {
Assert.assertEquals(t.getName(), NAME, "Name is not the provided one");
Assert.assertFalse(t.isRunning(), "Initial state of the timer is running");
Assert.assertEquals(t.getElapsedTime(), 0.0, "New timer elapsed time should be 0");
Assert.assertEquals(t.getElapsedTimeNano(), 0l, "New timer elapsed time nano should be 0");
t.start();
Assert.assertTrue(t.isRunning(), "Started timer isn't running");
Assert.assertTrue(t.getElapsedTime() >= 0.0, "Elapsed time should be >= 0");
Assert.assertTrue(t.getElapsedTimeNano() >= 0.0, "Elapsed time nano should be >= 0");
long n1 = t.getElapsedTimeNano();
double t1 = t.getElapsedTime();
idleLoop(); // idle loop to wait a tiny bit of time
long n2 = t.getElapsedTimeNano();
double t2 = t.getElapsedTime();
Assert.assertTrue(t2 >= t1, "T2 >= T1 for a running time");
Assert.assertTrue(n2 >= n1, "T2 >= T1 nano for a running time");
t.stop();
Assert.assertFalse(t.isRunning(), "Stopped timer still running");
long n3 = t.getElapsedTimeNano();
double t3 = t.getElapsedTime();
idleLoop(); // idle loop to wait a tiny bit of time
double t4 = t.getElapsedTime();
long n4 = t.getElapsedTimeNano();
Assert.assertTrue(t4 == t3, "Elapsed times for two calls of stop timer not the same");
Assert.assertTrue(n4 == n3, "Elapsed times for two calls of stop timer not the same");
t.restart();
idleLoop(); // idle loop to wait a tiny bit of time
double t5 = t.getElapsedTime();
long n5 = t.getElapsedTimeNano();
Assert.assertTrue(t.isRunning(), "Restarted timer should be running");
idleLoop(); // idle loop to wait a tiny bit of time
double t6 = t.getElapsedTime();
long n6 = t.getElapsedTimeNano();
Assert.assertTrue(t5 >= t4, "Restarted timer elapsed time should be after elapsed time preceding the restart");
Assert.assertTrue(t6 >= t5, "Second elapsed time not after the first in restarted timer");
Assert.assertTrue(n5 >= n4, "Restarted timer elapsed time nano should be after elapsed time preceding the restart");
Assert.assertTrue(n6 >= n5, "Second elapsed time nano not after the first in restarted timer");
final List<Double> secondTimes = Arrays.asList(t1, t2, t3, t4, t5, t6);
final List<Long> nanoTimes = Arrays.asList(n1, n2, n3, n4, n5, n6);
for ( int i = 0; i < nanoTimes.size(); i++ )
Assert.assertEquals(
SimpleTimer.nanoToSecondsAsDouble(nanoTimes.get(i)),
secondTimes.get(i), 1e-1, "Nanosecond and second timer disagree");
}
private final static void idleLoop() {
@Test
public void testNanoResolution() {
SimpleTimer t = new SimpleTimer(NAME);
// test the nanosecond resolution
long n7 = t.currentTimeNano();
int sum = 0;
for ( int i = 0; i < 100; i++) sum += i;
long n8 = t.currentTimeNano();
final long delta = n8 - n7;
final long oneMilliInNano = TimeUnit.MILLISECONDS.toNanos(1);
logger.warn("nanoTime before nano operation " + n7);
logger.warn("nanoTime after nano operation of summing 100 ints " + n8 + ", sum = " + sum + " time delta " + delta + " vs. 1 millsecond in nano " + oneMilliInNano);
Assert.assertTrue(n8 > n7, "SimpleTimer doesn't appear to have nanoSecond resolution: n8 " + n8 + " <= n7 " + n7);
Assert.assertTrue(delta < oneMilliInNano,
"SimpleTimer doesn't appear to have nanoSecond resolution: time delta is " + delta + " vs 1 millisecond in nano " + oneMilliInNano);
}
@Test
public void testMeaningfulTimes() {
SimpleTimer t = new SimpleTimer(NAME);
t.start();
for ( int i = 0; i < 100; i++ ) ;
long nano = t.getElapsedTimeNano();
double secs = t.getElapsedTime();
Assert.assertTrue(secs > 0, "Seconds timer doesn't appear to count properly: elapsed time is " + secs);
Assert.assertTrue(secs < 0.01, "Fast operation said to take longer than 10 milliseconds: elapsed time in seconds " + secs);
Assert.assertTrue(nano > 0, "Nanosecond timer doesn't appear to count properly: elapsed time is " + nano);
final long maxTimeInMicro = 100;
final long maxTimeInNano = TimeUnit.MICROSECONDS.toNanos(100);
Assert.assertTrue(nano < maxTimeInNano, "Fast operation said to take longer than " + maxTimeInMicro + " microseconds: elapsed time in nano " + nano + " micro " + TimeUnit.NANOSECONDS.toMicros(nano));
}
private static void idleLoop() {
for ( int i = 0; i < 100000; i++ ) ; // idle loop to wait a tiny bit of time
}
}