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

Slower method for a certain code path (cannot reoptimize a deoptimized method?)

XMLWordPrintable

      ADDITIONAL SYSTEM INFORMATION :
      The slow down was reproduced on JDK 1.8.0_252, JDK 11.0.7, JDK 13 (2019-09-17) and JDK 14.0.1

      OS 5.3.0-46-generic #38~18.04.1-Ubuntu, also on different hardware.

      A DESCRIPTION OF THE PROBLEM :
      We have a test suite Measurement (predates JMH but similar purpose) that ensures that we do not introduce a regression in GraphHopper (an open source routing engine, see https://github.com/graphhopper/graphhopper). We are also part of the JDK Quality Outreach: https://wiki.openjdk.java.net/display/quality/Quality+Outreach

      When I run one case called "routingCH" 5000 times (see the method Measurement.printTimeOfRouteQuery in the branch potential_jdk_issue) then on my laptop it gives me around 1.1ms per call. Changing the 5000 is easy (measurement.count) and also repeating the whole test (e.g. measurement.repeats=10) and of course we do a warmup before (measurement.count/3). So our numbers are reproducible and have helped us in the past to identify performance problems in *our* code.

      Now, when you enable runExtraCode (measurement.count_new_edge_tests=5000) which is run before the routingCH case, then routingCH slows down by ~10%! This is unexpected.

      Over the last week we tried to ensure this is not a bug in our code and also it does not seem to be a GC problem. Our guess is the following: in runExtraCode the method CHEdgeIterator.getWeight is called many times and causes a deoptimization of the method CustomWeighting.calcEdgeWeight (or some of the methods in that method) and this calcEdgeWeight method is also used for routingCH but somehow it never optimizes it again like it would be without runExtraCode.

      Please let me know if you need more information about our system or this test.

      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      We have created a special branch to make it easy for you to reproduce it (requires mvn in the classpath):

      git clone git@github.com:graphhopper/graphhopper.git
      cd graphhopper/
      git checkout potential_jdk_issue
      ./run_potential_jdk_issue.sh

      The values for routingCH.mean are stored in potential_jdk_issue.dat (first column) for every run and you should see that as soon as measurement.count_new_edge_tests is 5000 (third column) the value for routingCH.mean increases by ~10%. (You can ignore routingCH.distance_mean)

      EXPECTED VERSUS ACTUAL BEHAVIOR :
      EXPECTED -
      The expected result is that the speed of "routingCH" is independent of previous code.
      ACTUAL -
      routingCH slows down when runExtraCode is included

      ---------- BEGIN SOURCE ----------
      See "Steps to Reproduce"
      ---------- END SOURCE ----------

      CUSTOMER SUBMITTED WORKAROUND :
      None known

      FREQUENCY : always


            neliasso Nils Eliasson (Inactive)
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            9 Start watching this issue

              Created:
              Updated:
              Resolved: