JDK-8167431 : javac takes too long time to resolve interface dependency
  • Type: Bug
  • Component: tools
  • Sub-Component: javac
  • Affected Version: 8,9
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2016-10-09
  • Updated: 2016-11-07
  • Resolved: 2016-11-01
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9 b143Fixed
Related Reports
Relates :  
Description
FULL PRODUCT VERSION :
java version "1.8.0_102"
Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)

FULL OS VERSION :
Darwin JasonMBP2014.local 16.0.0 Darwin Kernel Version 16.0.0: Mon Aug 29 17:56:20 PDT 2016; root:xnu-3789.1.32~3/RELEASE_X86_64 x86_64

A DESCRIPTION OF THE PROBLEM :
The Scala programming language is in the process of migrating to Java 8. As part of this, we have started to use default methods in interfaces in our standard library.

We have noticed a regression in the startup time of applications. Steps to reproduce are below.

I profiled this and noticed the most of the time is spent in HierarchyVisitor<FindMethodsByErasedSig>. 

Inspection of this code suggest to me that it does not guard against redundant work when there are multiple paths to a particular super interface through the super-type lattice.

Related discussion: https://github.com/scala/scala/pull/5429

"redundancy" of super interfaces is fairly common in our collections hierarchy:

scala> def interfaceCount(cls: Class[_]) = {
  val m = collection.mutable.Map[Class[_], Int]().withDefaultValue(0)
  def loop(cls1: Class[_]) 
    cls1.getInterfaces.foreach(i => m(i) = (m(i) + 1))
    cls1.getInterfaces.foreach(loop)
    if (cls1.getSuperclass != null) loop(cls1.getSuperclass)
  }
  loop(cls)
  m
}
interfaceCount: (cls: Class[_])scala.collection.mutable.Map[Class[_],Int]

scala> println(interfaceCount(Nil.getClass).toSeq.sortBy(-_._2).mkString("\n"))
(interface scala.collection.GenTraversableOnce,75)
(interface scala.collection.Parallelizable,58)
(interface scala.collection.GenTraversableLike,58)
(interface scala.collection.generic.HasNewBuilder,32)
(interface scala.collection.GenIterableLike,26)
(interface scala.Equals,19)
(interface scala.collection.TraversableOnce,17)
(interface scala.collection.generic.FilterMonadic,17)
(interface scala.collection.TraversableLike,17)
(interface scala.collection.generic.GenericTraversableTemplate,15)
(interface scala.collection.GenTraversable,15)
(interface scala.collection.IterableLike,10)
(interface scala.collection.GenSeqLike,8)
(interface scala.collection.GenIterable,8)
(interface scala.collection.Traversable,7)
(interface scala.collection.SeqLike,5)
(interface scala.collection.Iterable,5)
(interface scala.collection.Seq,3)
(interface scala.PartialFunction,3)
(interface scala.Function1,3)
(interface scala.collection.GenSeq,3)
(interface java.io.Serializable,2)
(interface scala.collection.LinearSeqLike,2)
...


THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: Yes

THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Yes

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
For instance, running a small main method in the standard library that depends on the Scala standard collections and prints some system properties to console:

Scala 2.11.8 (no default methods, available from http://scala-lang.org/download/2.11.8.html)


% time java -classpath ~/scala/2.11.8/lib/scala-library.jar scala.util.Properties
Scala library version 2.11.8 -- Copyright 2002-2016, LAMP/EPFL

real	0m0.262s
user	0m0.260s
sys	0m0.044s

Scala 2.12.0-RC1 (uses default methods, available from http://scala-lang.org/download/2.12.0-RC1.html)

% time java -classpath ~/scala/2.12.0-RC1/lib/scala-library.jar scala.util.Properties
Scala library version 2.12.0-RC1 -- Copyright 2002-2016, LAMP/EPFL

real	0m0.891s
user	0m0.877s
sys	0m0.074s

EXPECTED VERSUS ACTUAL BEHAVIOR :
Expected: Comparable startup performance to before
Actual: 0.55s startup regression
REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
I not yet created a Java benchmark to demonstrate this problem, but I can do so if requested.
---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
 - Restructure interface hierarchy to avoid excessive redundancy and depth
 - Avoid using default methods


Comments
There seems to be several factors affecting the performance of the compiler. So far I have found that patch for JDK-8072480 and in particular the changes to Scope.java provoked a slowdown in the compiler. I doesn't seem to be the only cause though
14-10-2016

Small test case should have compiled in 0.5 seconds it took more then 3 minutes in JDK8 and more then 70 minutes in JDK9.
10-10-2016

Issue is reproducible with 8 and 9, below is the result == 8u112 == -sh-4.1$ time /opt/java/jdk1.8.0_112/bin/javac Test.java && time /opt/java/jdk1.8.0_112/bin/java Test real 3m1.065s user 2m56.897s sys 0m3.375s real 0m0.627s user 0m0.344s sys 0m0.258s == 9 ea b-139 takes 71 minutes -sh-4.1$ time /opt/java/jdk-9_ea-139/bin/javac Test.java && time /opt/java/jdk-9_ea-139/bin/java Test real 71m31.068s user 70m46.446s sys 0m23.535s real 0m0.913s user 0m0.065s sys 0m0.081s Running in verbose mode == -sh-4.1$ time /opt/java/jdk-9_ea-139/bin/javac -verbose Test.java [parsing started SimpleFileObject[/home/fmatte/JI/9044407/Test.java]] [parsing completed 28ms] [loading /modules/java.management/module-info.class] [loading /modules/java.scripting/module-info.class] [loading /modules/jdk.jdi/module-info.class] [loading /modules/jdk.internal.opt/module-info.class] [loading /modules/java.jnlp/module-info.class] [loading /modules/jdk.jconsole/module-info.class] [loading /modules/jdk.xml.dom/module-info.class] [loading /modules/jdk.javadoc/module-info.class] [loading /modules/jdk.plugin.server/module-info.class] [loading /modules/java.corba/module-info.class] [loading /modules/java.rmi/module-info.class] [loading /modules/jdk.management.jfr/module-info.class] [loading /modules/java.prefs/module-info.class] [loading /modules/jdk.management/module-info.class] [loading /modules/jdk.jshell/module-info.class] [loading /modules/jdk.deploy.controlpanel/module-info.class] [loading /modules/java.naming/module-info.class] [loading /modules/jdk.net/module-info.class] [loading /modules/jdk.vm.ci/module-info.class] [loading /modules/javafx.base/module-info.class] [loading /modules/jdk.unsupported/module-info.class] [loading /modules/java.smartcardio/module-info.class] [loading /modules/javafx.swing/module-info.class] [loading /modules/java.sql/module-info.class] [loading /modules/java.compiler/module-info.class] [loading /modules/jdk.packager.services/module-info.class] [loading /modules/jdk.snmp/module-info.class] [loading /modules/java.base/module-info.class] [loading /modules/jdk.dynalink/module-info.class] [loading /modules/jdk.hotspot.agent/module-info.class] [loading /modules/javafx.fxml/module-info.class] [loading /modules/jdk.naming.rmi/module-info.class] [loading /modules/jdk.sctp/module-info.class] [loading /modules/java.desktop/module-info.class] [loading /modules/jdk.rmic/module-info.class] [loading /modules/jdk.zipfs/module-info.class] [loading /modules/jdk.javaws/module-info.class] [loading /modules/jdk.vm.cds/module-info.class] [loading /modules/java.compact2/module-info.class] [loading /modules/java.security.jgss/module-info.class] [loading /modules/java.instrument/module-info.class] [loading /modules/java.datatransfer/module-info.class] [loading /modules/jdk.jvmstat/module-info.class] [loading /modules/jdk.accessibility/module-info.class] [loading /modules/jdk.jdwp.agent/module-info.class] [loading /modules/jdk.plugin.dom/module-info.class] [loading /modules/jdk.security.auth/module-info.class] [loading /modules/jdk.deploy/module-info.class] [loading /modules/java.xml.bind/module-info.class] [loading /modules/javafx.controls/module-info.class] [loading /modules/jdk.jcmd/module-info.class] [loading /modules/java.compact1/module-info.class] [loading /modules/jdk.jfr/module-info.class] [loading /modules/jdk.jsobject/module-info.class] [loading /modules/java.xml/module-info.class] [loading /modules/jdk.crypto.pkcs11/module-info.class] [loading /modules/javafx.web/module-info.class] [loading /modules/java.annotations.common/module-info.class] [loading /modules/java.logging/module-info.class] [loading /modules/jdk.management.cmm/module-info.class] [loading /modules/java.se/module-info.class] [loading /modules/java.compact3/module-info.class] [loading /modules/jdk.management.resource/module-info.class] [loading /modules/jdk.xml.ws/module-info.class] [loading /modules/java.se.ee/module-info.class] [loading /modules/jdk.compiler/module-info.class] [loading /modules/jdk.packager/module-info.class] [loading /modules/jdk.plugin/module-info.class] [loading /modules/jdk.httpserver/module-info.class] [loading /modules/jdk.scripting.nashorn/module-info.class] [loading /modules/jdk.jartool/module-info.class] [loading /modules/javafx.graphics/module-info.class] [loading /modules/jdk.jstatd/module-info.class] [loading /modules/jdk.scripting.nashorn.shell/module-info.class] [loading /modules/java.xml.ws/module-info.class] [loading /modules/jdk.xml.bind/module-info.class] [loading /modules/jdk.internal.le/module-info.class] [loading /modules/java.xml.crypto/module-info.class] [loading /modules/jdk.deploy.controlpanel.fx/module-info.class] [loading /modules/jdk.jdeps/module-info.class] [loading /modules/jdk.charsets/module-info.class] [loading /modules/jdk.naming.dns/module-info.class] [loading /modules/jdk.security.jgss/module-info.class] [loading /modules/java.sql.rowset/module-info.class] [loading /modules/java.transaction/module-info.class] [loading /modules/jdk.crypto.ec/module-info.class] [loading /modules/jdk.attach/module-info.class] [loading /modules/jdk.jlink/module-info.class] [loading /modules/jdk.localedata/module-info.class] [loading /modules/jdk.policytool/module-info.class] [loading /modules/java.security.sasl/module-info.class] [loading /modules/java.activation/module-info.class] [loading /modules/javafx.deploy/module-info.class] [loading /modules/jdk.pack200/module-info.class] [loading /modules/java.httpclient/module-info.class] [loading /modules/javafx.media/module-info.class] [search path for source files: .] [search path for class files: /opt/java/jdk-9_ea-139/lib/modules,.] [loading /modules/java.base/java/lang/Object.class] [loading /modules/java.base/java/lang/String.class] [loading /modules/java.base/java/lang/Deprecated.class] [loading /modules/java.base/java/lang/annotation/Retention.class] [loading /modules/java.base/java/lang/annotation/RetentionPolicy.class] [loading /modules/java.base/java/lang/annotation/Target.class] [loading /modules/java.base/java/lang/annotation/ElementType.class] [checking Test] [loading /modules/java.base/java/io/Serializable.class] [loading /modules/java.base/java/lang/AutoCloseable.class]
10-10-2016