Bad timing using System.currentTimeMillis() instead of System.nanoTime()

Sometimes people report performance concerns to me complete with actual times. While this makes me happy (as compared to the also popular report that "its slow"), I always have to ask "how did you time it". In Java the answer is very often something similar to:

long timeMillis = System.currentTimeMillis();
//do something to be timed
timeMillis = System.currentTimeMillis() - timeMillis; 
System.out.println("millis: " + timeMillis);

Sometimes it's in a loop to trap averages, standard deviation, has pre-runs to try to eliminate timing JIT steps, and so on. However, the API choice means this is not going to work terribly well. The issue is that currentTimeMillis() "Returns the current time in milliseconds. Note that while the unit of time of the return value is a millisecond, the granularity of the value depends on the underlying operating system and may be larger. For example, many operating systems measure time in units of tens of milliseconds." (see docs). This issue is theoretically common knowledge, yet it keeps on coming up, particularly from coders who did most of their learning on Java 1.4.2.

In Java 1.5 an API allowing access to the high resolution timer was finally added, System.nanoTime() (see docs).

Knowing that times around tens of milliseconds are the probably a good point to see problems we can whip up a quick and dirty little program to demonstrate the problem with using System.currentTimeMillis():

public class TimeTest {
 public static void main(String...argv) throws Exception {
  
  int spins = 99;
  int sleepMillis = 12;
  
  for (int i=0; i<spins; i++) {
   long timeMillis = System.currentTimeMillis();
   Thread.sleep(sleepMillis);
   timeMillis = System.currentTimeMillis() - timeMillis; 
   System.out.println("millis: " + timeMillis);
  }
  
  for (int i=0; i<spins; i++) {
   long timeNanos = System.nanoTime();
   Thread.sleep(sleepMillis);
   timeNanos = System.nanoTime() - timeNanos;
   long timeMillis = timeNanos / (1000 * 1000);
   System.out.println("millis from nanos: " + timeMillis + ", nanos: " + timeNanos);
  }  
 }
}

The results on a Windows 2k3 Java 1.6.0_21-b07 system tend to 15 or 16 with fairly regular 0's; nanoTime is bang on:


millis: 16
millis: 0
millis: 15
millis: 16
millis from nanos: 12, nanos: 12557445
millis from nanos: 12, nanos: 12593718
millis from nanos: 12, nanos: 12423730
millis from nanos: 12, nanos: 12576676


On a Solaris 5.10 VM the results are somewhat better:


millis: 12
millis: 12
millis: 12
millis: 12
millis from nanos: 12, nanos: 12051729
millis from nanos: 12, nanos: 12113813
millis from nanos: 12, nanos: 12089188
millis from nanos: 12, nanos: 12013906


Mac OS X also appears to have a more accurate currentTimeMillis(), with Java 1.6.0_22:


millis: 12
millis: 12
millis: 12
millis: 12
millis from nanos: 12, nanos: 12111000
millis from nanos: 12, nanos: 12087000
millis from nanos: 12, nanos: 12096000
millis from nanos: 12, nanos: 12083000


Moral of story: if you read no other manual, at least read the one for your timing API! Consider reading Robust Java Benchmarking parts 1 and 2 as well.