While investigating

6440250: System.nanoTime() is 25x slower than System.currentTimeMillis()

I noticed the following anomaly:

The following (bad) microbenchmark:

-------------------------
class MicroBenchmark {
    abstract static class Job {
private final String name;
Job(String name) { this.name = name; }
String name() { return name; }
abstract void work() throws Throwable;
    }

    private static void collectAllGarbage() {
try {
for (int i = 0; i < 2; i++) {
System.gc(); System.runFinalization(); Thread.sleep(10);
}
} catch (InterruptedException e) { throw new Error(e); }
    }

    /**
     * Runs each job for long enough that all the runtime compilers
     * have had plenty of time to warm up, i.e. get around to
     * compiling everything worth compiling.
     * Returns array of average times per job per run.
     */
    private static long[] time0(Job ... jobs) throws Throwable {
final long warmupNanos = 10L * 1000L * 1000L * 1000L;
long[] nanoss = new long[jobs.length];
for (int i = 0; i < jobs.length; i++) {
collectAllGarbage();
long t0 = System.nanoTime();
long t;
int j = 0;
do { jobs[i].work(); j++; }
while ((t = System.nanoTime() - t0) < warmupNanos);
nanoss[i] = t/j;
}
return nanoss;
    }

    private static void time(Job ... jobs) throws Throwable {

long[] warmup = time0(jobs); // Warm up run
long[] nanoss = time0(jobs); // Real timing run

final String nameHeader = "Method";
int nameWidth = nameHeader.length();
for (Job job : jobs)
nameWidth = Math.max(nameWidth, job.name().length());

final String millisHeader = "Millis";
int millisWidth = millisHeader.length();
for (long nanos : nanoss)
millisWidth =
Math.max(millisWidth,
String.format("%d", nanos/(1000L * 1000L)).length());

final String ratioHeader = "Ratio";
int ratioWidth = ratioHeader.length();

String format = String.format("%%-%ds %%%dd %%.3f%%n",
nameWidth, millisWidth);
String headerFormat = String.format("%%-%ds %%-%ds %%-%ds%%n",
nameWidth, millisWidth, ratioWidth);
System.out.printf(headerFormat, "Method", "Millis", "Ratio");

// Print out absolute and relative times, calibrated against first job
for (int i = 0; i < jobs.length; i++) {
long millis = nanoss[i]/(1000L * 1000L);
double ratio = (double)nanoss[i] / (double)nanoss[0];
System.out.printf(format, jobs[i].name(), millis, ratio);
}
    }

    private static int intArg(String[] args, int i, int defaultValue) {
return args.length > i ? Integer.parseInt(args[i]) : defaultValue;
    }

    private static void deoptimize(long x) {
if (x == 289374930472L) throw new Error();
    }
    
    public static void main(String[] args) throws Throwable {
final int iterations = intArg(args, 0, 10000000);
time(
new Job("nanoTime") { void work() {
//long x = 0;
for (int i = 0 ; i < iterations; i++)
System.nanoTime();
//x += System.nanoTime();
//deoptimize(x);
}},
new Job("currentTimeMillis") { void work() {
//long x = 0;
for (int i = 0 ; i < iterations; i++)
System.currentTimeMillis();
//x += System.currentTimeMillis();
//deoptimize(x);
}}
);
    }
}
-------------------------

produces the following results:

 $ for f in -client -server; do jver 6 jr $f MicroBenchmark.java; done
==> javac -source 1.6 -Xlint:all MicroBenchmark.java
==> java -client -esa -ea MicroBenchmark
Method Millis Ratio
nanoTime 56 1.000
currentTimeMillis 55 0.997
==> javac -source 1.6 -Xlint:all MicroBenchmark.java
==> java -server -esa -ea MicroBenchmark
Method Millis Ratio
nanoTime 2287 1.000
currentTimeMillis 1852 0.810

Of course, the benchmark is flawed in that calls to the methods being
measured can simply be optimized away
(they need to be deoptimized as shown by the comments).

But why can't c2 see what c1 sees?
Does c2 not recognize these methods as side-effect-free?