System.nanoTime vs System.currentTimeMillis

Question

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.

Imbalance

It would be unreasonable to expect that your origin would be exactly the same for all calls - after all, you're calling two methods... there can be varying lengths of time between those two calls, each time you call the pair. – Ipomoea

@JonSkeet That is also what I said in my answer. He is calling the offset repeated times. – Informative

System.nanoTime is the raw system clock, using the finest resolution available. It is essentially whatever the OS provides. currentTimeMillis is the system time "cleaned up" a bit to have a consistent base. But both are a the mercy of the OS. And, given the realities of modern multiprocessors, there is apt to be some thread-to-thread difference. Java can't do any better than what it has to work with. – Dowlen

This question has some interesting tidbits: #510962 – Foreandaft

Answer 1

As has been mentioned, computing a new origin each time means you are subject to error.

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

If you modify your program so you also compute the origin difference, you'll find out it's very small. About 200ns average I measured which is about right for the time delay.

Using multiplication instead of division (which should be OK without overflow for another couple hundred years) you'll also find that the number of origins computed that fail the equality check is much larger, about 99%. If the reason for error is because of the time delay, they would only pass when the delay happens to be identical to the last one.

A much simpler test is to accumulate elapsed time over some number of subsequent calls to nanoTime and see if it checks out with 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;
        }
    }
}

That test does indicate the origin is the same (or at least the error is zero-mean).

Foreandaft

OK, there is no way to ensure the thread computing millitime and nanotime is not affected by OS scheduling between those calls. That does not really explain differences in the 10ms range. As for the origin computation, I wanted to limit my precision to milliSeconds since that is the resolution provided my currentTimeMillis. I miss out on any nano-jitter, though. I could actually extend my test a bit to bracket my nano sample between two milli samples and consider only those samples where both milli samples match. That would get rid of any scheduling issues. – Imbalance

@RalfH Did you get any differences larger than 10ms? I didn't when I ran it. The thing is that nanoTime would be useless for statistics if the origin were allowed to "jump around" because then subsequent calls could read unrelated numbers. Instead, you'd be looking for very small changes. That's why your test method is problematic, because your margin for error is too large to prove anything. Especially since the documentation says the origin cannot change. – Foreandaft

See my updated question. The 10ms jumps are gone, so I assume they were due to the thread getting thrown out by the OS scheduler. The smaller jumps however stayed. Also, there seem to be differences in nano origin between threads/cores, which suggests that I can not compute meaningful differences between nano time stamps taken on different cores. – Imbalance

Answer 2

As far as I know the method System.currentTimeMillis() makes indeed sometimes jumps, dependent on the underlying OS. I have observed this behaviour myself sometimes.

So your code gives me the impression you try to get the offset between System.nanoTime() and System.currentTimeMillis() repeated times. You should rather try to observe this offset by calling System.currentTimeMillis() only once before you can say that System.nanoTimes() causes sometimes jumps.

By the way, I will not pretend that the spec (javadoc describes System.nanoTime() related to some fixed point) is always perfectly implemented. You can look on this discussion where multi-core CPUs or changes of CPU-frequencies can negatively affect the required behaviour of System.nanoTime(). But one thing is sure. System.currentTimeMillis() is far more subject to arbitrary jumps.

Informative

Great answer. I've posted a question just now, maybe you'd like to give your two cents? #66789644 – Stichous