Community
Participate
Working Groups
Created attachment 269986 [details] jvisualvm compilation profiling Something makes JDT compiler super-slow. I have tried to reduce the problem to a test case but it is not easy. I get the problem every time I try to compile RxJava 2. This project compiles normally (ex. 'gradlew clean compileJava') in less than 10seconds but it takes minutes (~4min) in eclipse compiler. gradle compilation > BUILD SUCCESSFUL > Total time: 9.936 secs eclipse compilation > 2017-08-26T16:36:31.150Z Compiling with eclipse compiler… > 2017-08-26T16:39:57.425Z eclipse compiler done! Pretty poor performance test, but it anyways demonstrates that there is something wrong. With jvisualvm I have seen that the problem is related to this method which is consuming most of the time. org.eclipse.jdt.internal.compiler.lookup.AnnotatableTypeSystem.getWildcard(…) 63.113827 17,405 ms (63.1%) 7051 Reproduce it in a minimal project is difficult, I think the easier way to reproduce is to clone RxJava project and point JDT compiler to this source folder. Something like this (the unique dependency required is 'org.reactivestreams:reactive-streams:1.0.0', add it to the classpath): System.out.println(Instant.now() + " Compiling with eclipse compiler…"); BatchCompiler.compile("-source 1.8 -proc:none ../RxJava/src/main/java", new PrintWriter(out), new PrintWriter(err), new CompilationProgress() { @Override public void begin(int remainingWork) { } @Override public void done() { } @Override public boolean isCanceled() { return false; } @Override public void setTaskName(String name) { } @Override public void worked(int workIncrement, int remainingWork) { } }); System.out.println(Instant.now() + " eclipse compiler done!"); I think any JDT developer can just add a test case with something similar to this code (temporary, of course ;) ) and try to find which kind of generics (type variables on class o method, arguments, functional interfaces, all of them) is causing the poor performance. org.eclipse.jdt.internal.compiler.lookup.TypeSystem.types seem to be the critical field, containing an enormous array. I think might be related to https://bugs.eclipse.org/bugs/show_bug.cgi?id=434326 This JDK type resolution performance problem might be useful https://bugs.openjdk.java.net/browse/JDK-8051946
Thanks for your detailed report. Currently Java 9 related work has priority, but a few comments I can give already: If AnnotatableTypeSystem is indeed the culprit there should be an easy workaround, since that class serves no other purpose than to truthfully implement JSR 308 style annotations. The following settings should ensure that AnnotatableTypeSystem is not used during compilation: - no annotation-based null analysis (-warn:-nullAnnot), is default - no annotation processing (-proc:none) - storeAnnotations disabled - default, no CLI option, in .prefs this would be org.eclipse.jdt.core.compiler.storeAnnotations=disabled If your experiments happened indeed with the options mentioned in comment 0, then s.t. weird is going on if AnnotatableTypeSystem is touched at all. Unfortunately, we can't just add arbitrary 3rd-party libraries to our tests (for IP reasons). Still for analysis on a local machine the provided steps should be useful. The link to the JDK bug is only mildly related for several reasons. First and foremost it directly refers to implementation details of javac, that have no correspondence in ecj. Second, it relates to the overall type checking / inference strategy, whereas the profiler screenshot shows time spent in a compilation phase before type checking (MethodVerifier checks things like illegal overrides, missing implementation for abstract methods, need for bridge methods and such).
Thank you for your time! Yep, I think the problem is in TypeSystem, I had already disabled 'storeAnnotations', actually, the project has 0 type annotations. FYI I'm actually a GWT developer, and GWT uses JDT compiler internally so this problem makes im-practical to compile RxJava 2.0 in GWT. And, I already saw that the problem is not in the AnnotatableTypeSystem bc I had already tested the compilation with similar options (https://github.com/ibaca/gwt/commit/774b676d4d659194871f9010a6c0b821f4a76622) without luck! Java 9 should be a priority, but this problem looks like an all-version performance problem so... hehe might be a good idea to fix it as soon as possible XD. I have personal interest, but, anyway is kind of sad that it is "obvious" that no rxjava developer has been using eclipse, or maybe they have tried, but you really should use netbeans or intellij because with this problem your eclipse project takes >4minutes (consuming a lot of memory and cpu) to just stop compiling! A project usually compiled in a few seconds. I have updated the profiling screenshot with thoes flags activated and uploaded a pretty poor but easy to use test case (required to clone RxJava in a sibling folder) here https://github.com/ibaca/jdt-bug-521438. Also the result of a -agentlib:hprof: CPU SAMPLES BEGIN (total = 87132) Sun Aug 27 18:33:11 2017 rank self accum count trace method 1 61,57% 61,57% 53648 300136 java.net.SocketInputStream.socketRead0 2 18,94% 80,51% 16499 300898 java.net.PlainSocketImpl.socketAccept 3 17,96% 98,47% 15652 301207 org.eclipse.jdt.internal.compiler.lookup.TypeSystem.getWildcard 4 0,16% 98,63% 139 301048 java.io.FileInputStream.readBytes 5 0,14% 98,77% 119 301255 org.eclipse.jdt.internal.compiler.lookup.TypeSystem.getWildcard 6 0,10% 98,87% 89 301342 sun.management.ThreadImpl.dumpThreads0 7 0,08% 98,95% 73 301251 java.lang.Object.hashCode 8 0,07% 99,02% 61 301346 java.lang.System.identityHashCode 9 0,04% 99,06% 34 301003 java.lang.Thread.yield 10 0,04% 99,10% 32 301267 org.eclipse.jdt.internal.compiler.lookup.TypeSystem.getWildcard 11 0,03% 99,13% 25 301284 java.net.SocketOutputStream.socketWrite0 12 0,02% 99,14% 15 301348 java.lang.Class.forName0 13 0,02% 99,16% 15 301300 java.lang.Object.hashCode 14 0,02% 99,18% 15 300066 java.lang.ClassLoader.defineClass1 15 0,01% 99,19% 12 301224 java.io.FileOutputStream.open0 16 0,01% 99,21% 12 301093 java.io.FileInputStream.available 17 0,01% 99,22% 10 301400 java.lang.String.intern 18 0,01% 99,23% 10 301290 org.eclipse.jdt.internal.compiler.lookup.TypeSystem$HashedParameterizedTypes$InternalParameterizedTypeBinding.hashCode 19 0,01% 99,24% 9 301264 org.eclipse.jdt.internal.compiler.lookup.ParameterizedTypeBinding.initialize
Created attachment 269990 [details] typesystem sampler cpu
Created attachment 269991 [details] typesystem snapshot cpu
Thanks for the additional data. I had a quick look at the code in question, to check if this could be a recent regression, but found no changes that raise further suspicion. As far as I can see the compiler has always held all types that are "derived" from a common generic type in an array, requiring linear lookup during the interning operations like #getWildcard(). Obviously the assumption was made, that the number of different types derived from the same original will never be huge. The code of RxJava seems to prove this assumption wrong. At a closer look there is a close connection to bug 434326, indeed: the other bug introduced hashed lookup for parameterizations of a common generic type. Quite likely the exact same strategy can be applied to wildcard derivation as well (in the hope, that such additional infra structure will not penalize the normal case with small numbers of wildcards). More questions: Are you aware of older JDT versions that perform better in this regard? How does incremental compilation perform, meaning: does the problem occur on each save or only when cleanly compiling the entire project?
Tested with jdt.core (<3.10 do not support java8) 12min 56sec 3.13.0.v20170614-0247 (repo.eclipse) 10min 50sec 3.13.0.v20170614-0247 (repo.eclipse) 03min 25sec 3.13.0.v20170109-1908 (repo.eclipse) 03min 15sec 3.13.0.v20160802-1726 (repo.eclipse) 03min 28sec 3.12.3 (central) 03min 32sec 3.12.2 (central) 03min 20sec 3.11.1.v20150902-1521 (repo.eclipse) 03min 31sec 3.11.1.v20150902-1521 (repo.eclipse) 08min 23sec 3.10.0 (central) Incremental compilation is super slow too. For example, just removing an annotation from the Flowable type and saving the file takes for the "building workspace" task more than 1minute. I have no time to continue testing now (so I'll upload this results), maybe I try to find the exact version it makes it slow again in 3.13 (https://repo.eclipse.org/content/repositories/eclipse/org/eclipse/jdt/org.eclipse.jdt.core/maven-metadata.xml).
Looks like the hash strategy is even worst, from version 3.13.0.v20170308 to 3.13.0.v20170502 it gets 3 times slower most of the time spent in TreeNode.find. Also note that even we are comparing 3min, 8min or even >10min, all this time are crazy slow, this project should compile in a few seconds. Actually, the 3min (which here appear to be the fastest one) is the one that makes impossible to work with RxJava 2.x and impossible to use RxJava 2.x in GWT. So, thanks again to trying to advance here even if the max priority is java9. 3.13.0.v20170308-1510 PT3M15.682S self accum count trace method 47,47% 97,39% 15612 300651 …compiler.lookup.TypeSystem.getWildcard 3.13.0.v20170502-1108 PT10M45.637S self accum count trace method 32,84% 82,81% 35600 300669 java.util.HashMap$TreeNode.find 15,98% 98,79% 17322 300662 …compiler.lookup.TypeSystem.getWildcard
I suspect this is caused by my change for bug 508799, which removed "id" from the hash function (because it gets changed for instances that are already in the hashtable.) I'll try to reproduce the problem.
(In reply to Till Brychcy from comment #8) > I suspect this is caused by my change for bug 508799, which removed "id" > from the hash function (because it gets changed for instances that are > already in the hashtable.) > > I'll try to reproduce the problem. I've confirmed the suspicion (about the increase). I already have a draft patch that restores the performance to the pre-bug 508799 level. (I haven't looked for possible optimizations of TypeSystem.getWildcard yet)
New Gerrit change created: https://git.eclipse.org/r/104684
Created attachment 270120 [details] Testcase I have a test case that causes the compiler to take a really long time (almost hang-like). Not sure if it is relevant. If it requires a different bug, please let me know so I can raise one. The compiler seems to spend lot of time in InferenceContext18.addDependencies() and TypeVariableBinding.mentionsAny().
(In reply to Jay Arthanareeswaran from comment #11) > > I have a test case that causes the compiler to take a really long time > (almost hang-like). Not sure if it is relevant. If it requires a different > bug, please let me know so I can raise one. This is really a different issue, so a separate bug would be good. > > The compiler seems to spend lot of time in > InferenceContext18.addDependencies() and TypeVariableBinding.mentionsAny().
(In reply to Till Brychcy from comment #9) > (I haven't looked for possible optimizations of TypeSystem.getWildcard yet) ANALYSIS: The TypeSystem is used for the compilations of the whole project, and the wildcards are looked up via the derived type list of the generic type, so this list gets really long (esp. as captures and inference variables come into play). PATCH: If the wildcard has a typevariablebinding (or subclass) as bound, use the derived type list of this bound. This reduces compilation time from approx 3 minutes to approx 30 seconds. (Javac is still faster - it needs approx 7 seconds)
(In reply to Till Brychcy from comment #13) > PATCH: > If the wildcard has a typevariablebinding (or subclass) as bound, use the > derived type list of this bound. > > This reduces compilation time from approx 3 minutes to approx 30 seconds. > (Javac is still faster - it needs approx 7 seconds) By doing it also for bounds that are ParametrizedTypeBindings, compilation time goes down to approx. 5 seconds (Patch set 3)
This is amazing! I saw this Saturday night, Sunday morning I confirmed and tried to compile GWT with this patch, but sadly GWT uses 3.11.2 (Mars 4.5) and drop-in update to 3.13 doesn't work (need more time). Anyways, this is our problem. In my laptop also compiles in 5seconds, is pretty amazing! So this seems to solve the problem perfectly, I suppose (I have not gathered memory stats) that this should have an important implication both in CPU (obvious) and memory. You one question, what is the exact type of generic is causing the explosion? I ask this bc rxjava1 is pretty similar but the performance is reasonable, but in rxjava2 it move to 3min so must be some specific case which actually multiplies possible combination. I had tried to deduce this from the source code or even debugging, but I cannot see the difference between rxjava1 and rxjava2. If you don't have time, don't need to answer this, it is just curiosity. Thank you very much! GWT community will really appreciate this fix/improvement!
Gerrit change https://git.eclipse.org/r/104684 was merged to [master]. Commit: http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/?id=48a3a3eb7ea3d5a31b91fda5c892849f5bc403c6
(In reply to Eclipse Genie from comment #16) > Gerrit change https://git.eclipse.org/r/104684 was merged to [master]. > Commit: > http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/ > ?id=48a3a3eb7ea3d5a31b91fda5c892849f5bc403c6 Released for 4.8M3
*** Bug 500416 has been marked as a duplicate of this bug. ***
Verified for 4.8 M3 with build I20171023-2000
*** Bug 528761 has been marked as a duplicate of this bug. ***
Can this be downported to 4.7.3?
A backport to 4.7.x would be great, especially since 4.8 is scheduled mid-late 2018! I've been suffering from this for at least 1.5 years by now since I'm the main developer on the RxJava 2 library that sparked this particular report.
Reopening for the backport
Backport to 4.7 will be pretty useful for GWT too! I have applied it manually to 4.6 (https://github.com/ibaca/eclipse.jdt.core/commit/995495659bddcaf193c0107f8489e698624ceea7) and created a custom GWT build to make it work with RxJava 2.0 too. Easy to backport and works perfectly! Thanks.
(In reply to Lars Vogel from comment #23) > Reopening for the backport Let's please await Jay's +1 for back port. If he agrees, I volunteer for reviewing (given that this is a non-trivial change in a sensitive area).
(In reply to Stephan Herrmann from comment #25) > Let's please await Jay's +1 for back port. > > If he agrees, I volunteer for reviewing (given that this is a non-trivial > change in a sensitive area). +1 for backport
(In reply to Jay Arthanareeswaran from comment #26) > +1 for backport Till or Stephan, can you cherry-pick 48a3a3eb7ea3d5a31b91fda5c892849f5bc403c6 onto R4_7_maintenance and push it to Gerrit? I cannot do this, as only committers can push on behave to others.
New Gerrit change created: https://git.eclipse.org/r/115275
(In reply to Eclipse Genie from comment #28) > New Gerrit change created: https://git.eclipse.org/r/115275 Till, anything special needed for this patch? If not, can it be pushed?
(In reply to Jay Arthanareeswaran from comment #29) > (In reply to Eclipse Genie from comment #28) > > New Gerrit change created: https://git.eclipse.org/r/115275 > > Till, anything special needed for this patch? If not, can it be pushed? I think this can be pushed. Of course, Stephan wrote he'd volunteer to review it, if you want a second opinion.
I figured it would be could if I familiarize myself with this change for future work in this area :) First, even for a pure performance fix, it would help if we had a test where we can inspect the effect of this change. I failed to use the example from comment 2 as I have no gradle support in my JDT workspace (and its runtime workbench). @Till, do you have anything in this direction (ideally self contained) that you could share? For lack of a real performance test suite, would XLargeTests be a suitable home for such a test? Part one of the change, where you improve how derived types are balanced within TypeSystem.types[] looks good, but I could use some help understanding that this change is complete. I see that (A)TS.getWildcard() now use a different slot, but could s.o. else insert the wildcard via some other path into TypeSystem.cacheDerivedTypes(), which might not be aware of the new strategy? Could s.t. like this lead to undue duplication of a type binding? If not, please explain :) Part two where you add more treatment re URB to PTBKey (renamed from InternalParameterizedTypeBinding) looks unrelated, can you explain why that change is needed? This is how far I got: - you preferred to create a sibling of PTB rather than a child, why? - due to that change you need to copy some code from the ctor of PTB, right? - same for swapUnresolved So, why? If PTBKey is used only as a key into hashedParameterizedTypes, is setting #tagBits needed at all here? OTOH, if relevant then the logic seems incomplete (see last 4 lines of PTB.<init>()). Unrelatedly: did anyone follow up on comment 11 f.?
(In reply to Stephan Herrmann from comment #31) > I figured it would be could if I familiarize myself with this change for > future work in this area :) > > First, even for a pure performance fix, it would help if we had a test where > we can inspect the effect of this change. I failed to use the example from > comment 2 as I have no gradle support in my JDT workspace (and its runtime > workbench). > @Till, do you have anything in this direction (ideally self contained) that > you could share? For lack of a real performance test suite, would > XLargeTests be a suitable home for such a test? Sorry, No. > > Part one of the change, where you improve how derived types are balanced > within TypeSystem.types[] looks good, but I could use some help > understanding that this change is complete. I see that (A)TS.getWildcard() > now use a different slot, but could s.o. else insert the wildcard via some > other path into TypeSystem.cacheDerivedTypes(), which might not be aware of > the new strategy? Could s.t. like this lead to undue duplication of a type > binding? If not, please explain :) The WildcardBinding-constructor is only invoked in (A)TS.getWildcard() and in clone(). All clone invocations except the one in ATS.getAnnotatedType() are for types other than WildcardBinding, and ATS.getAnnotatedType() has handling for the new strategy. > > Part two where you add more treatment re URB to PTBKey (renamed from > InternalParameterizedTypeBinding) looks unrelated, can you explain why that > change is needed? This is how far I got: > - you preferred to create a sibling of PTB rather than a child, why? > - due to that change you need to copy some code from the ctor of PTB, right? > - same for swapUnresolved > So, why? As simplification, to make clear that these are just used as hash keys and can never escape and be used as real PTBs (so there is no need to look at this class if you do anything related to PTBs - I often was confused by them in type hierarchies etc. before this change). > > If PTBKey is used only as a key into hashedParameterizedTypes, is setting > #tagBits needed at all here? OTOH, if relevant then the logic seems > incomplete (see last 4 lines of PTB.<init>()). Looks like a copy-paste left-over, but I can't really remember - anyway, shouldn't hurt, but we might consider removing this on the master later. > > > Unrelatedly: did anyone follow up on comment 11 f.? Yes, Bug 522444
So should we proceed with the backport?
not backported
This is a showstopper. With this bug one full compile needs about 10minutes. Wihtout this bug we need about 1 1/2 minute. We need roundabout 5-8 full compiles every day, that makes one hour for every worker every day. That's really expensive and definetly a showstopper. We are still using Eclipse 4.6. We've tried 4.8M5, but that compiler crashes all the time, so that's no alternative. Same speed with 4.7. Please think again about backporting to 4.6/4.7. That's an expensive bug!
(In reply to Jens Bruhn-Hansel from comment #35) > We are still using Eclipse 4.6. We've tried 4.8M5, but that compiler crashes > all the time, so that's no alternative. Same speed with 4.7. Have you created bug reports? > > Please think again about backporting to 4.6/4.7. That's an expensive bug! @Jay, @Manoj, @Stephan, WDYT?
(In reply to Till Brychcy from comment #36) > (In reply to Jens Bruhn-Hansel from comment #35) > > We are still using Eclipse 4.6. We've tried 4.8M5, but that compiler crashes > > all the time, so that's no alternative. Same speed with 4.7. > Have you created bug reports? I can only emphasize this. @Jens, now is the time to help ensure that 4.8 will have no show stoppers for you. > > Please think again about backporting to 4.6/4.7. That's an expensive bug! > > @Jay, @Manoj, @Stephan, WDYT? No objections from my side. All questions in comment 31 have been answered.
(In reply to Stephan Herrmann from comment #37) > No objections from my side. All questions in comment 31 have been answered. +1 for downport from a PMC member
(In reply to Stephan Herrmann from comment #37) > > @Jay, @Manoj, @Stephan, WDYT? > > > No objections from my side. All questions in comment 31 have been answered. @Jay, @Manoj, I have already updated the gerrit. But declaration of RC2 is already ongoing (bug 531180), so I don't know how to proceed.
(In reply to Till Brychcy from comment #39) > But declaration of RC2 is already ongoing (bug 531180), so I don't know how > to proceed. I suggest asking PMC for a rebuild. See https://bugs.eclipse.org/bugs/show_bug.cgi?id=531180#c2
Gerrit change https://git.eclipse.org/r/115275 was merged to [R4_7_maintenance]. Commit: http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/?id=149eb43900ffc0e4fa53b5f93b96dc49a8e36410
(In reply to Eclipse Genie from comment #41) > Gerrit change https://git.eclipse.org/r/115275 was merged to > [R4_7_maintenance]. > Commit: > http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/ > ?id=149eb43900ffc0e4fa53b5f93b96dc49a8e36410 Released for 4.7.3
great news, thanks!
Verified for 4.7.3 RC2 with build M20180215-0545
same here, 4.7.3 RC2 with build M20180215-0545 is fast, very cool!
