JDK-6440430 : C2 does not optimize away pointless calls to nanoTime, currentTimeMillis
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 6,9,10
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • OS: generic
  • CPU: generic
  • Submitted: 2006-06-19
  • Updated: 2019-10-12
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
tbdUnresolved
Related Reports
Relates :  
Relates :  
Description
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?

Comments
System.nanoTime()/currentTimeMillis() may be considered "pure" and benefit from JDK-8218414.
12-10-2019

EVALUATION C2 needs to note that intrinsified functions are side-effect free, a capability not currently implemented. This shouldn't be hard to add.
20-06-2006