System.nanoTime vs System.currentTimeMillis

Question

According to its documentation, System.nanoTime returns nanoseconds from some fixed but arbitrary start time. However, on all x64 machines, I tried the code below, there were temporary transitions moving this fixed start time. There may be some flaw in my method to get the correct time using an alternative method (here, currentTimeMillis). However, the main purpose of measuring relative times (durations) is also adversely affected.

I ran into this problem trying to measure delays when comparing different queues with LMAX Disruptor, where sometimes very negative delays occur. In these cases, the start and end time stamps were created by different threads, but the delay was calculated after the completion of these threads.

My code here takes time using nanoTime, computes a fixed origin in currentTimeMillis time, and compares this origin between calls. And since I have to ask a question here: what is wrong with this code? Why does he abide by contract breaches with a fixed origin? Or is it not so?

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 have made small changes. Basically, I bind nanoTime calls between two currentTimeMillis calls to see if a thread has been ported (which should take more than the current TimeMillis resolution). In this case, I ignore the loop cycle. In fact, if we know that nanoTime is fast enough (like on newer architectures like Ivy Bridge), we can copy to currentTimeMillis with nanoTime.

Now long jumps of 10 ms have disappeared. Instead, we count when we get more than 2 ms from the first source per stream. On the computers that I tested, for a run time of 100, there are always about 200,000 transitions between calls. It is for these cases that I think that either currentTimeMillis or nanoTime may be inaccurate.

Answer 1

As already mentioned, calculating a new source every time means that you are prone to errors.

 // ______ delay _______ // vv long origin = (long)(System.currentTimeMillis() - System.nanoTime() / 1e6); // ^ // truncation 

If you change your program so that you also calculate the difference in origin, you will find it very small. About 200 ns, the average I measured, which roughly corresponds to the time delay.

Using multiplication instead of division (which should be OK without overflowing for another couple of hundred years), you will also find that the number of calculations that do not match the equality check is much larger, about 99%. If the cause of the error is associated with a time delay, they will only occur when the delay is identical to the latter.

It is much easier to check the accumulation of elapsed time for a number of subsequent nanoTime calls and see if it is checked using the first and last calls:

 public class SimpleTimeCoherencyTest { public static void main(String[] args) { final long anchorNanos = System.nanoTime(); long lastNanoTime = System.nanoTime(); long accumulatedNanos = lastNanoTime - anchorNanos; long numCallsSinceAnchor = 1L; for(int i = 0; i < 100; i++) { TestRun testRun = new TestRun(accumulatedNanos, lastNanoTime); Thread t = new Thread(testRun); t.start(); try { t.join(); } catch(InterruptedException ie) {} lastNanoTime = testRun.lastNanoTime; accumulatedNanos = testRun.accumulatedNanos; numCallsSinceAnchor += testRun.numCallsToNanoTime; } System.out.println(numCallsSinceAnchor); System.out.println(accumulatedNanos); System.out.println(lastNanoTime - anchorNanos); } static class TestRun implements Runnable { volatile long accumulatedNanos; volatile long lastNanoTime; volatile long numCallsToNanoTime; TestRun(long acc, long last) { accumulatedNanos = acc; lastNanoTime = last; } @Override public void run() { long lastNanos = lastNanoTime; long currentNanos; do { currentNanos = System.nanoTime(); accumulatedNanos += currentNanos - lastNanos; lastNanos = currentNanos; numCallsToNanoTime++; } while(currentNanos - lastNanoTime <= 100000000L); lastNanoTime = lastNanos; } } } 

This test indicates that the origin is the same (or at least the error is zero).

Answer 2

As far as I know, the System.currentTimeMillis() method sometimes makes transitions that depend on the underlying OS. I sometimes observed this behavior.

So your code gives me the impression that you are trying to get an offset between System.nanoTime() and System.currentTimeMillis() repeating times. You should rather try to notice this bias by calling System.currentTimeMillis() only once before you can say that System.nanoTimes() sometimes causes transitions.

By the way, I will not pretend that the specification (javadoc describes System.nanoTime() associated with some fixed point) is always perfectly implemented. You can look in this discussion where multi-core processors or changes in processor frequency can adversely affect the required behavior of System.nanoTime() . But one thing is certain. System.currentTimeMillis() much more prone to arbitrary jumping.