What's wrong with System.nanoTime?

Question

I have a very long string with the pattern </value> at the very end, I am trying to test the performance of some function calls, so I made the following test to try to find out the answer... but I think I might be using nanoTime incorrectly? Because the result doesn't make sense no matter how I swap the order around...

  long start, end;

  start = System.nanoTime();
  StringUtils.indexOf(s, "</value>");
  end = System.nanoTime();
  System.out.println(end - start);

  start = System.nanoTime();
  s.indexOf("</value>");      
  end = System.nanoTime();
  System.out.println(end - start);

  start = System.nanoTime();
  sb.indexOf("</value>");
  end = System.nanoTime();
  System.out.println(end - start);

I get the following:

163566    // StringUtils
395227    // String
30797     // StringBuilder

165619    // StringBuilder
359639    // String
32850     // StringUtils

No matter which order I swap them around, the numbers will always be somewhat the same... What's the deal here?

From java.sun.com website's FAQ:

Using System.nanoTime() between various points in the code to perform elapsed time measurements should always be accurate.

Also:

http://download.oracle.com/javase/1.5.0/docs/api/java/lang/System.html#nanoTime()

Answer 1

The differences between the two runs is in the order of microseconds and that is expected. There are many things going on on your machine which make the execution environment never the same between two runs of your application. That is why you get that difference.

EDIT: Java API says:

This method provides nanosecond precision, but not necessarily nanosecond accuracy.

Answer 2

Most likely there's memory initialization issues or other things that happen at the JVM's startup that is skewing your numbers. You should get a bigger sample to get more accurate numbers. Play around with the order, run it multiple times, etc.

Answer 3

It is more than likely that the methods you check use some common code behind the scenes. But the JIT will do its work only after about 10.000 invocations. Hence, this could be the cause why your first two example seem to be always slower.

Quick fix: just do the 3 method calls before the first measuring on a long enoug string.