Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6876279

currentTimeMillis and nanoTime are too expensive

    Details

    • Type: Enhancement
    • Status: Closed
    • Priority: P3
    • Resolution: Not an Issue
    • Affects Version/s: 6u10
    • Fix Version/s: None
    • Component/s: hotspot
    • Labels:
    • Subcomponent:
    • CPU:
      x86
    • OS:
      linux

      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 ----------

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                rlewis Roger Lewis (Inactive)
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Imported:
                  Indexed: