JDK-6876279 : currentTimeMillis and nanoTime are too expensive
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 6u10
  • Priority: P3
  • Status: Closed
  • Resolution: Not an Issue
  • OS: linux
  • CPU: x86
  • Submitted: 2009-08-26
  • Updated: 2010-08-16
  • Resolved: 2010-08-16
Related Reports
Relates :  
Relates :  
Description
FULL PRODUCT VERSION :
java version "1.6.0_14"
Java(TM) SE Runtime Environment (build 1.6.0_14-b08)
Java HotSpot(TM) 64-Bit Server VM (build 14.0-b16, mixed mode)


ADDITIONAL OS VERSION INFORMATION :
Linux eqny-concmp148 2.6.9-55.9.ELsmp #1 SMP Tue Jun 19 07:44:28 EDT 2007 x86_64 x86_64 x86_64 GNU/Linux


A DESCRIPTION OF THE PROBLEM :
currentTimeMillis and nanoTime take too long.  The problem with currentTimeMillis is that in previous JVM versions, it did NOT take so long to invoke.  On my test box, using a previous version of jdk 6 (more detail in the "Expected Result"), currentTimeMillis took ~7 nanoseconds per invocation when AggressiveOpts was turned on.  With the most recent jdk release, it takes ~1600 nanoseconds per invocation regardless of the VM parameters used.  That is a TREMENDOUS difference.  nanoTime seems to take about 1700 nanoseconds regardless of which JVM version I am using.

I view the change in currentTimeMillis performance as a regression.  We have a process which takes timestamps periodically in a performance critical thread (i.e., a timestamp every X number of work units) where the time taken by each work unit is <~5 microseconds.  The impact to that thread of a monitoring operation jumping from 7 nanoseconds to 1600 nanoseconds is appreciable.

The nanoTime problem is related:  for performance tuning we wanted to get timings of individual work units in the performance critical thread.  When the work unit takes on the order of 5 microseconds, a nanosecond timestamp which takes nearly 2 microseconds is untenable.  I think nanoTime is somewhat dangerous because it takes 3 orders of magnitude longer than the unit of measure to simply capture the data.  I understand that nanoTime taking a long time is longstanding practice for the JVM, and I can see where Sun would argue this isn't a bug, but I would disagree.  I know the OS/processor have different possible sources for time information of varying resolution and quality.  I would, of course, like the time taken to be less, but at the very least, I think there should be an option to switch to a potentially less accurate time-source with VM parameters if you determine that the current time source is the most acceptable and no further performance can be wrung from it.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Previous VM used:

java version "1.6.0_04"
Java(TM) SE Runtime Environment (build 1.6.0_04-b12)
Java HotSpot(TM) 64-Bit Server VM (build 10.0-b19, mixed mode)

Ran with these args:   -server -Xmx512m -Xms512m -classpath . TimeTest
and these args:  -server -Xmx512m -Xms512m -XX:+AggressiveOpts -classpath . TimeTest

On the previous VM, currentTimeMillis is VERY fast with AggressiveOpts turned on, and is slow with it off.  On the current VM, currentTimeMillis is always slow.  nanoTime is always slow.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
On 6_04, when run with these args:   -server -Xmx512m -Xms512m -classpath . TimeTest

Got these results:
(-5969766634379734168, 1586)
(2726207840868594128, 1714)
----------------
(-5969766303727858989, 1593)
(3057331922010144128, 1713)
----------------
(-5969765973638253657, 1586)
(3387566685694613128, 1714)
----------------
(-5969765643540274976, 1586)
(3717669196249078128, 1717)
----------------
(-5969765313250308891, 1583)
(4048683082001548128, 1730)
----------------
(-5969764981699458022, 1583)
(4379122219179394128, 1718)
----------------
(-5969764651440654923, 1586)
(4709050965047397128, 1712)
----------------
(-5969764320273260861, 1623)
(5043791767064524128, 1736)
----------------
(-5969763982626736976, 1644)
(5382133140123729128, 1736)
----------------
(-5969763644799623367, 1640)
(5719495467393566128, 1732)
----------------


When run with these args:  -server -Xmx512m -Xms512m -XX:+AggressiveOpts -classpath . TimeTest

Got these results:

(-5969780613609248728, 7)
(7116639654879895744, 1734)
----------------
(-5969780439516704532, 6)
(7290575409461648744, 1744)
----------------
(-5969780264430737336, 6)
(7467049760744457744, 1772)
----------------
(-5969780086514975772, 6)
(7646086160862618744, 1787)
----------------
(-5969779907065085464, 6)
(7825166354542747744, 1782)
----------------
(-5969779728224142659, 6)
(8004417960393444744, 1789)
----------------
(-5969779548632611052, 6)
(8183729792805574744, 1784)
----------------
(-5969779369592267024, 6)
(8362959675630581744, 1787)
----------------
(-5969779190192841248, 6)
(8542307992744581744, 1784)
----------------
(-5969779011093944144, 6)
(8721315808356238744, 1785)
----------------


ACTUAL -
When run with jdk 1.6.0_14, I tried a variety of JVM options (and both client and server vms) with no appreciable difference.  I saw no way of replicating the performance seen with 1.6.0_04.

These results are with these options: -server -Xmx512m -Xms512m -XX:+AggressiveOpts -classpath . TimeTest
(-5969761937528532121, 1588)
(7423114020213276128, 1706)
----------------
(-5969761607922986299, 1594)
(7753453458213697128, 1712)
----------------
(-5969761277662124676, 1583)
(8083305216988700128, 1718)
----------------
(-5969760947251042943, 1585)
(8413971601401608128, 1722)
----------------
(-5969760616448988044, 1584)
(8744309259763070128, 1732)
----------------
(-5969760281644629659, 1646)
(9085153452502839128, 1773)
----------------
(-5969759939628594170, 1647)
(-9019601646128498488, 1771)
----------------
(-5969759597651913071, 1649)
(-8677595916429941488, 1770)
----------------
(-5969759255717233019, 1655)
(-8334739645739868488, 1772)
----------------
(-5969758912889138350, 1648)
(-7992629265868667488, 1772)
----------------



REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
public class TimeTest{
   public static void main(String[] args){
      final int iters = 10000000;

      try{
         for (int asdf = 0; asdf < 10; asdf++){
            {
               long start = System.nanoTime();
               long acc   = 0;

               for (int i = 0; i < iters; i++){
                  // accumulated value kept solely to prevent any HotSpot determination that the return value isn't used
                  acc += System.currentTimeMillis();
               }

               long end = System.nanoTime();

               System.out.println("(" + acc + ", " + ((end - start) / iters) + ")");
            }

            {
               long start = System.nanoTime();
               long acc   = 0;

               for (int i = 0; i < iters; i++){
                  // accumulated value kept solely to prevent any HotSpot determination that the return value isn't used
                  acc += System.nanoTime();
               }

               long end = System.nanoTime();

               System.out.println("(" + acc + ", " + ((end - start) / iters) + ")");
            }

            System.out.println("----------------");
         }
      }
      catch (Throwable e){
         e.printStackTrace();
      }
   }
}
---------- END SOURCE ----------

Comments
EVALUATION 1.6.0_04 included an experimental optimization (enabled as part of AggressiveOpts) that cached the value returned by currentTimeMillis so as to reduce the number of calls to gettimeofday - which is the inherent reason these calls are slow. By 1.6.0_14 that optimization has been removed because it caused more problems than it solved. Both currentTimeMillis and nanoTime utilize direct OS system calls to either the time-of-day clock, or the highest-resolution clock source available (respectively). Hence performance is limited by the performance of the underlying OS. In the case of nanoTime, once we have support for reliable-TSC in the hardware and the OS, then we will see a marked performance improvement. If the OS uses this to underpin the TOD clock as well then currentTimeMillis() will also improve.
16-08-2010

PUBLIC COMMENTS Fundamentally currentTimeMillis and nanoTime simply use the OS time services: - currentTimeMillis uses the time-of-day clock as per its specification - nanoTime uses the highest resolution time source available on the platform However due to historical (and continual) bugs in those OS time services the VM has evolved to add extra code - in particular for nanoTime ensuring that it is a monotonic non-decreasing time source as required. There is already a CR to have nanoTime simply use the OS time source if the user is prepared to set a flag that says "I trust the time source on this OS" - see 6864866 Performance of currentTimeMillis has been raised in a number of CRs. But ultimately we're depending on the time-of-day call in the OS. There is some discussion (a littel dated but still relevant) of time source issues on different OS on my blog: http://blogs.sun.com/dholmes/entry/inside_the_hotspot_vm_clocks I'm unclear of what performance difference would be encountered using AggressiveOpts in JDK6 but I will look into it. I need to check that the simple benchmark is not seeing compilation effects rather than changes to these actual calls. [Edited to add references to other CRs]
14-08-2010