EDIT: While I do agree that the key to this problem hinges around the accuracy of Thread.sleep(), I have been lead to believe that Thread.sleep() is bias towards sleeping longer than requested. Why would the thread resume before its sleep duration has expired? I can understand the OS scheduler not making it back around to the thread in time to wake it, but why would it get there earlier? What would be the point of sleeping threads if the OS could just arbitrarily wake them up early?
I am attempting to write a class to do modular timing in my projects. The idea is to make a class capable of measuring the execution time of any particular piece of code in which I am interested. I want to do this measuring without having to write specific timing code in-place and provide myself a clean modular interface.
The concept is built around a coach having multiple stopwatches for each of his runners. I can call one class with different stopwatch ID's to create threads that measure their respective relative execution times. In addition, there is a lap functionality to measure sub-intervals of the watch's clock. The implementation is centered around the use of a HashMap by both the Stopwatch (coach) class and the Watch (runner) class.
Here is my implementation:
import java.util.HashMap;
import java.util.Map;
import java.util.Map.Entry;
public class Stopwatch {
private static Map<String, Watch> watchMap = new HashMap<>();
public static boolean start( String watchID ) {
if( !watchMap.containsKey( watchID ) ) {
watchMap.put(watchID, new Watch() );
return true;
} else {
return false;
}
}
public static void stop( String watchID ) {
if( watchMap.containsKey(watchID) ) {
watchMap.get(watchID).stop();
}
}
public static void startLap( String watchID, String lapID ) {
if( watchMap.containsKey(watchID) ) {
watchMap.get(watchID).startLap(lapID);
}
}
public static void endLap( String watchID, String lapID ) {
if( watchMap.containsKey(watchID) ) {
watchMap.get(watchID).stopLap(lapID);
}
}
public static void stopAndSystemPrint( String watchID ) {
if( watchMap.containsKey(watchID)) {
Watch watch = watchMap.get(watchID);
if( watch.isRunning() ) {
watch.stop();
}
Map<String, Long> lapMap = watch.getLapMap();
System.out.println("/****************** " + watchID
+ " *******************\\" );
System.out.println("Watch started at: " + watch.getStartTime()
+ " nanosec" );
for( Entry<String, Long> lap : lapMap.entrySet() ) {
System.out.println("\t" + lap.getKey() + ": "
+ ((double)lap.getValue() / 1000000.0)
+ " msec" );
}
System.out.println("Watch ended at: " + watch.getEndTime()
+ " nanosec" );
System.out.println("Watch total duration: "
+ (double)(watch.getDuration() / 1000000.0 )
+ " msec" );
System.out.println("\\****************** " + watchID
+ " *******************/\n\n");
}
}
private static class Watch implements Runnable {
private Thread timingThread;
private long startTime;
private long currentTime;
private long endTime;
private volatile boolean running;
private Map<String, Long> lapMap;
public Watch() {
startTime = System.nanoTime();
lapMap = new HashMap<>();
running = true;
timingThread = new Thread( this );
timingThread.start();
}
@Override
public void run() {
while( isRunning() ) {
currentTime = System.nanoTime();
// 0.5 Microsecond resolution
try {
Thread.sleep(0, 500);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
public void stop() {
running = false;
endTime = System.nanoTime();
}
public void startLap( String lapID ) {
lapMap.put( lapID, currentTime );
}
public void stopLap( String lapID ) {
if( lapMap.containsKey( lapID ) ) {
lapMap.put(lapID, currentTime - lapMap.get(lapID) );
}
}
public Map<String, Long> getLapMap() {
return this.lapMap;
}
public boolean isRunning() {
return this.running;
}
public long getStartTime() {
return this.startTime;
}
public long getEndTime() {
return this.endTime;
}
public long getDuration() {
if( isRunning() ) {
return currentTime - startTime;
} else {
return endTime - startTime;
}
}
}
}
And, here is the code I am using to test this implementation:
public class StopwatchTest {
public static void main(String[] args) throws InterruptedException {
String watch1 = "watch1";
Stopwatch.start( watch1 );
String watch2 = "watch2";
Stopwatch.start(watch2);
String watch3 = "watch3";
Stopwatch.start(watch3);
String lap1 = "lap1";
Stopwatch.startLap( watch1, lap1 );
Stopwatch.startLap( watch2, lap1 );
Thread.sleep(13);
Stopwatch.endLap( watch1, lap1 );
String lap2 = "lap2";
Stopwatch.startLap( watch1, lap2 );
Thread.sleep( 500 );
Stopwatch.endLap( watch1, lap2 );
Stopwatch.endLap( watch2, lap1 );
Stopwatch.stop(watch3);
String lap3 = "lap3";
Stopwatch.startLap(watch1, lap3);
Thread.sleep( 5000 );
Stopwatch.endLap(watch1, lap3);
Stopwatch.stop(watch1);
Stopwatch.stop(watch2);
Stopwatch.stop(watch3);
Stopwatch.stopAndSystemPrint(watch1);
Stopwatch.stopAndSystemPrint(watch2);
Stopwatch.stopAndSystemPrint(watch3);
}
}
Finally, an output that this test can produce:
/****************** watch1 *******************\
Watch started at: 45843652013177 nanosec
lap1: 12.461469 msec
lap2: 498.615724 msec
lap3: 4999.242803 msec
Watch ended at: 45849165709934 nanosec
Watch total duration: 5513.696757 msec
\****************** watch1 *******************/
/****************** watch2 *******************\
Watch started at: 45843652251560 nanosec
lap1: 4.5844165436787E7 msec
Watch ended at: 45849165711920 nanosec
Watch total duration: 5513.46036 msec
\****************** watch2 *******************/
/****************** watch3 *******************\
Watch started at: 45843652306520 nanosec
Watch ended at: 45849165713576 nanosec
Watch total duration: 5513.407056 msec
\****************** watch3 *******************/
There are a few interesting (to me, at least) results from this code.
One, is that the watches finish early or late on the order of 1 millisecond. I would have thought that, albeit with a somewhat inaccurate nanosecond clock, that I could get better accuracy than 1 ms. Perhaps I am forgetting something about significant figures and accuracy.
Another, is that, in this test result, watch2 finishes with this result for its lap:
Watch started at: 45843652251560 nanosec
lap1: 4.5844165436787E7 msec
Watch ended at: 45849165711920 nanosec
I checked the way I was manipulating the value in my stopAndSystemPrint method, but that doesn't seem to have any effect on the error. I can only conclude that the math I am doing there is solid, and that something before that is broken sometimes. The sometimes bit worries me because - I think - it tells me that I'm probably doing something wrong with my thread in the Watch class. It appears that the lap duration is being thrown off and resulting in some value between my start time and end time.
I am not sure these issues are exclusive, but if I had to pick one to solve, it would be the jitter.
Can someone make heads or tails of why there would be jitter on the order of 1ms?
Bonus: Why do the watches get messed up lap durations from time-to-time?
The watches get messed up from time to time because you are performing the calculations in a thread that reads currentTime that is different from the thread that writes currentTime. As a result, sometimes the value that is read is uninitialized - that is, zero. In the specific case you mention involving watch2, a zero lap start time was recorded because the initial currentTime value was not available to the thread recording the lap start time.
To fix this, declare currentTime to be volatile. You may also need to put in a delay or yield to permit the watch to do one time update before starting any laps.
As for the jitter, the fact that currentTime is not volatile may be some or all of the problem since the calling thread for starts and stops may be dealing with stale data. In addition, Thread.sleep() is accurate only to the degree the system clock is accurate, which in most systems is not nanosecond accuracy. More information on the latter should be available at the possible duplicate Basilevs mentions in the comment.