System.nanoTime vs System.currentTimeMillis
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"
+ "nt" + lnf.format( tc.numMismatchToFirst) + " different from first origin (" + lnf.format( 100.0 * tc.numMismatchToFirst / nruns) + "%)"
+ "nt" + lnf.format( tc.numMismatchToLast) + " jumps from last origin (" + lnf.format( 100.0 * tc.numMismatchToLast / nruns) + "%)"
+ "nt" + lnf.format( tc.numMismatchToFirstBig) + " different from first origin by more than " + BIG_OFFSET_MS + " ms"
+ " (" + lnf.format( 100.0 * tc.numMismatchToFirstBig / nruns) + "%)"
+ "nt" + "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.
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).
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.