According to its documentation, System.nanoTime returns nanoseconds since some fixed but arbitrary origin time. However, on all x64 machines I tried the code below, there were time jumps, moving that fixed origin time around. There may be some flaw in my method to acquire the correct time using an alternative method (here, currentTimeMillis). However, the main purpose of measuring relative times (durations) is negatively affected, too.
I came across this problem trying to measure latencies when comparing different queues to LMAX's Disruptor where I got very negative latencies sometimes. In those cases, start and end timestamps were created by different threads, but the latency was computed after those threads had finished.
My code here takes time using nanoTime, computes the fixed origin in currentTimeMillis time, and compares that origin between calls. And since I must ask a question here: What is wrong with this code? Why does it observe violations of the fixed origin contract? Or does it not?
import java.text.*;
/**
* test coherency between {@link System#currentTimeMillis()} and {@link System#nanoTime()}
*/
public class TimeCoherencyTest {
static final int MAX_THREADS = Math.max( 1, Runtime.getRuntime().availableProcessors() - 1);
static final long RUNTIME_NS = 1000000000L * 100;
static final long BIG_OFFSET_MS = 2;
static long startNanos;
static long firstNanoOrigin;
static {
initNanos();
}
private static void initNanos() {
long millisBefore = System.currentTimeMillis();
long millisAfter;
do {
startNanos = System.nanoTime();
millisAfter = System.currentTimeMillis();
} while ( millisAfter != millisBefore);
firstNanoOrigin = ( long) ( millisAfter - ( startNanos / 1e6));
}
static NumberFormat lnf = DecimalFormat.getNumberInstance();
static {
lnf.setMaximumFractionDigits( 3);
lnf.setGroupingUsed( true);
};
static class TimeCoherency {
long firstOrigin;
long lastOrigin;
long numMismatchToLast = 0;
long numMismatchToFirst = 0;
long numMismatchToFirstBig = 0;
long numChecks = 0;
public TimeCoherency( long firstNanoOrigin) {
firstOrigin = firstNanoOrigin;
lastOrigin = firstOrigin;
}
}
public static void main( String[] args) {
Thread[] threads = new Thread[ MAX_THREADS];
for ( int i = 0; i < MAX_THREADS; i++) {
final int fi = i;
final TimeCoherency tc = new TimeCoherency( firstNanoOrigin);
threads[ i] = new Thread() {
@Override
public void run() {
long start = getNow( tc);
long firstOrigin = tc.lastOrigin; // get the first origin for this thread
System.out.println( "Thread " + fi + " started at " + lnf.format( start) + " ns");
long nruns = 0;
while ( getNow( tc) < RUNTIME_NS) {
nruns++;
}
final long runTimeNS = getNow( tc) - start;
final long originDrift = tc.lastOrigin - firstOrigin;
nruns += 3; // account for start and end call and the one that ends the loop
final long skipped = nruns - tc.numChecks;
System.out.println( "Thread " + fi + " finished after " + lnf.format( nruns) + " runs in " + lnf.format( runTimeNS) + " ns (" + lnf.format( ( double) runTimeNS / nruns) + " ns/call) with"
+ "\n\t" + lnf.format( tc.numMismatchToFirst) + " different from first origin (" + lnf.format( 100.0 * tc.numMismatchToFirst / nruns) + "%)"
+ "\n\t" + lnf.format( tc.numMismatchToLast) + " jumps from last origin (" + lnf.format( 100.0 * tc.numMismatchToLast / nruns) + "%)"
+ "\n\t" + lnf.format( tc.numMismatchToFirstBig) + " different from first origin by more than " + BIG_OFFSET_MS + " ms"
+ " (" + lnf.format( 100.0 * tc.numMismatchToFirstBig / nruns) + "%)"
+ "\n\t" + "total drift: " + lnf.format( originDrift) + " ms, " + lnf.format( skipped) + " skipped (" + lnf.format( 100.0 * skipped / nruns) + " %)");
}};
threads[ i].start();
}
try {
for ( Thread thread : threads) {
thread.join();
}
} catch ( InterruptedException ie) {};
}
public static long getNow( TimeCoherency coherency) {
long millisBefore = System.currentTimeMillis();
long now = System.nanoTime();
if ( coherency != null) {
checkOffset( now, millisBefore, coherency);
}
return now - startNanos;
}
private static void checkOffset( long nanoTime, long millisBefore, TimeCoherency tc) {
long millisAfter = System.currentTimeMillis();
if ( millisBefore != millisAfter) {
// disregard since thread may have slept between calls
return;
}
tc.numChecks++;
long nanoMillis = ( long) ( nanoTime / 1e6);
long nanoOrigin = millisAfter - nanoMillis;
long oldOrigin = tc.lastOrigin;
if ( oldOrigin != nanoOrigin) {
tc.lastOrigin = nanoOrigin;
tc.numMismatchToLast++;
}
if ( tc.firstOrigin != nanoOrigin) {
tc.numMismatchToFirst++;
}
if ( Math.abs( tc.firstOrigin - nanoOrigin) > BIG_OFFSET_MS) {
tc.numMismatchToFirstBig ++;
}
}
}
Now I made some small changes. Basically, I bracket the nanoTime calls between two currentTimeMillis calls to see if the thread has been rescheduled (which should take more than currentTimeMillis resolution). In this case, I disregard the loop cycle. Actually, if we know that nanoTime is sufficiently fast (as on newer architectures like Ivy Bridge), we can bracket in currentTimeMillis with nanoTime.
Now the long >10ms jumps are gone. Instead, we count when we get more than 2ms away from first origin per thread. On the machines I have tested, for a runtime of 100s, there are always close to 200.000 jumps between calls. It is for those cases that I think either currentTimeMillis or nanoTime may be inaccurate.