This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.
|Summary:||Empty ergonomics IDE starts more slowly than Java SE IDE (due many module dependencies)|
|Product:||platform||Reporter:||Jaroslav Tulach <jtulach>|
|Component:||Module System||Assignee:||Jaroslav Tulach <jtulach>|
|Severity:||blocker||CC:||anebuzelsky, apireviews, jglick, jtulach, ovk, tpavek|
|Issue Type:||DEFECT||Exception Reporter:|
|Bug Depends on:||165493|
Snapshot from Linux
Snapshot from Windows
Speedup by deleting premature optimizations. Can this patch be applied without major compatibility problems?
Oleg, Tomáši, can you remeasure the difference with new platform10 cluster included in this ZIP please?
The changes that improve caching - no need to parse the manifests to understand dependencies
Making Dependency serializable, caching deps for all modules
startup log from current build (20090407)
startup log from a build before the last change (20090331)
Improves what gets stored to caches so syntetic params are ignored
logs form build Apr 08
logs form build Apr 08
Description Jaroslav Tulach 2009-03-16 17:36:27 UTC
There is a rumor that the empty ergonomics IDE is slower than the Java SE one. I did a measurements on my Linux: Warm starts on revision 7800489394a9: Java SE: Preparation finished, took 3383ms Ergo : Preparation finished, took 3091ms After doing clean caches (echo 3 > /proc/sys/vm/drop_caches): Java SE: Preparation finished, took 39367ms Ergo : Preparation finished, took 38102ms So it seems that things are OK. Aren't they?
Comment 1 Jaroslav Tulach 2009-03-16 17:37:14 UTC
Oleg, can you please help me emulate the case when the ergonomics IDE will be slower? Thanks.
Comment 2 Jaroslav Tulach 2009-03-16 18:07:13 UTC
Btw. there was a hypothesis that the ergo build is slowed down by expensive recomputing of content of system file system. So I disabled that, assuming that all features are disabled and the result is still bad: After doing clean caches (echo 3 > /proc/sys/vm/drop_caches) with disabled waitFinished() on module system: Preparation finished, took 36584ms So the last thing that can slow things down is the parsing of XML layer feature files. If I disable that I can get to Preparation finished, took 2972ms in case of warm start and in case of slow one to: Preparation finished, took 36306ms But still, this is no big regression compared to anything anyway.
Comment 3 Oleg Khokhlov 2009-03-18 14:38:42 UTC
if we look at dashboard with cold startup results we can see that Ergo was always worse than Base IDE on WinXP. I attach logs with cold/warm ergo/base results. And I've checked on Linux as well - ergo is better on Linux.
Comment 5 Jaroslav Tulach 2009-03-22 15:13:45 UTC
OK. Under my VirtualBox WinXP it takes 8s for Java SE to start and 10s for ergonomics IDE.
Comment 6 Jaroslav Tulach 2009-03-22 17:12:01 UTC
Created attachment 78597 [details] Snapshot from Linux
Comment 7 Jaroslav Tulach 2009-03-22 17:12:56 UTC
Created attachment 78598 [details] Snapshot from Windows
Comment 8 Jaroslav Tulach 2009-03-22 17:17:43 UTC
The problem seems to be in XMLFileSystem. On Windows, the setURLs(...) method takes ages, because it does some expensive operation inside of XMLFileSystem*Ref*.lastModified method. This is a bit silly as all the entries are in the same JAR file and have almost the same timestamp (and moreover +- few seconds does not matter). Jirka, can you speed the parsing on Windows, please?
Comment 9 Jaroslav Tulach 2009-03-24 15:00:44 UTC
Created attachment 78752 [details] Speedup by deleting premature optimizations. Can this patch be applied without major compatibility problems?
Comment 10 Jiri Skrivanek 2009-03-25 09:50:25 UTC
I am not able to verify compatibility of proposed patch. Instead I added one item cache which is enough for this case. It decreases number of File.lastModified() call from 1395 to 2 on my windows. http://hg.netbeans.org/core-main/rev/7214b1cba18f
Comment 11 Quality Engineering 2009-03-26 14:33:59 UTC
Integrated into 'main-golden', will be available in build *200903260733* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress) Changeset: http://hg.netbeans.org/main-golden/rev/7214b1cba18f User: Jiri Skrivanek <email@example.com> Log: #160390 - One item cache to eliminate redundant File.lastModified queries.
Comment 12 Jaroslav Tulach 2009-04-03 13:01:51 UTC
Tomáš Pávek reports that the speed improvement is still not sufficient.
Comment 13 Jaroslav Tulach 2009-04-03 13:03:55 UTC
One reason for that seems to be that the module system needs to parse 673 manifests with ergonomics (although most of their modules is disabled), and only 347 when JavaSE IDE is starting.
Comment 14 Jaroslav Tulach 2009-04-03 13:06:16 UTC
Created attachment 79378 [details] Oleg, Tomáši, can you remeasure the difference with new platform10 cluster included in this ZIP please?
Comment 15 Jaroslav Tulach 2009-04-03 13:08:30 UTC
Created attachment 79379 [details] The changes that improve caching - no need to parse the manifests to understand dependencies
Comment 16 Jaroslav Tulach 2009-04-03 13:12:39 UTC
These changes reduce the time to ModuleSystem.readList from 2.5s to 0.5s on my Linux for ergonomics. I hope the change will be visible on Windows as well. The ModuleSystem.readList time for JavaSE edition is now 0.3s. Jesse, please review my changes and suggest proper APIs: #1 - OK to make Dependency serializable? This change allowed me to create its instances without parsing anything. #2 - Please suggest replacement for Module.deps, the goal is skip the parsing of dependencies in the manifest if this field is provided. Thanks.
Comment 17 Pavel Flaska 2009-04-03 14:15:11 UTC
Some preliminary measurements on WindowsXP machine. Custom build, NetBeans IDE Dev (Build 090403), existing userdir, 2nd and next runs. ModuleSystem.readList finished: 871ms 400ms 401ms 406ms Provided platform zip: 851ms 303ms 308ms 915ms
Comment 18 Jesse Glick 2009-04-03 14:36:38 UTC
Module.deps is OK for now, can always refactor into something prettier later. Comment '// Permit the concrete installer to make some changes:' probably now misplaced. Bug in extract method refactoring I think. Check compat against old userdir; 'deps = (Set<?>) ois.readObject();' would I guess fail. What happens then? If this is just a silent cache invalidation & recreation, then fine. Give Dependency an SVUID. Making Dependency implement Serializable is technically an API change, though a pretty trivial one. Mention in apichanges.xml.
Comment 19 Jaroslav Tulach 2009-04-03 16:40:38 UTC
Created attachment 79405 [details] Making Dependency serializable, caching deps for all modules
Comment 20 Jesse Glick 2009-04-03 17:39:26 UTC
I can't really evaluate patches when you move large blocks of code around for no good reason, as in ModuleList.ReadInitial or Module.initDeps. If you want to do reformatting or refactoring, please do it as separate changesets later, so the real patch is as short as possible. Do not use @SuppressWarnings("unchecked") when dealing with collection types. Use NbCollections. Typo: "Loades" Otherwise looks OK to me.
Comment 21 Jaroslav Tulach 2009-04-06 07:54:46 UTC
OK. Thanks for review.
Comment 22 Jaroslav Tulach 2009-04-06 08:17:42 UTC
Comment 23 Quality Engineering 2009-04-06 19:43:15 UTC
Integrated into 'main-golden', will be available in build *200904061400* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress) Changeset: http://hg.netbeans.org/main-golden/rev/37fedec08173 User: Jaroslav Tulach <firstname.lastname@example.org> Log: #160390: Cache module dependencies from previous run
Comment 24 Tomas Pavek 2009-04-07 16:49:53 UTC
After the last change the startup is rather longer than shorter (on Windows XP). * The ModuleSystem.readList block is not faster. * In addition there's about 3s in addition spent somewhere, it is visible in the startup log, though no specific operation is reported for it - it happens between these two checkpoints: @9937 - ModuleList.installNew finished, took 3645ms @13154 - ModuleList.trigger finished, took 6863ms
Comment 25 Tomas Pavek 2009-04-07 16:51:31 UTC
Created attachment 79663 [details] startup log from current build (20090407)
Comment 26 Tomas Pavek 2009-04-07 16:52:31 UTC
Created attachment 79664 [details] startup log from a build before the last change (20090331)
Comment 27 Jaroslav Tulach 2009-04-08 15:17:20 UTC
Created attachment 79745 [details] Improves what gets stored to caches so syntetic params are ignored
Comment 28 Jaroslav Tulach 2009-04-08 15:28:55 UTC
Comment 29 Oleg Khokhlov 2009-04-08 15:33:32 UTC
the latest results are very strange, like: <Test name="Base IDE w/o project" unit="ms" results="passed" threshold="18451" classname="org.netbeans.performance.ColdStartup"> <PerformanceData runOrder="1" value="19991"/> <PerformanceData runOrder="1" value="48163"/> <PerformanceData runOrder="1" value="19801"/> <PerformanceData runOrder="1" value="48535"/> <PerformanceData runOrder="1" value="20235"/> </Test> <Test name="Base IDE with project" unit="ms" results="passed" threshold="25325" classname="org.netbeans.performance.ColdStartup"> <PerformanceData runOrder="1" value="53650"/> <PerformanceData runOrder="1" value="22575"/> <PerformanceData runOrder="1" value="53043"/> <PerformanceData runOrder="1" value="22389"/> <PerformanceData runOrder="1" value="54680"/> attaching several last logs. Will wait until latest fix is in production build and will reopen if results are still bad.
Comment 30 Oleg Khokhlov 2009-04-08 15:34:20 UTC
Created attachment 79747 [details] logs form build Apr 08
Comment 31 Oleg Khokhlov 2009-04-08 15:34:27 UTC
Created attachment 79748 [details] logs form build Apr 08
Comment 32 Jaroslav Tulach 2009-04-08 16:42:33 UTC
This kind of jumping is exactly what the core-main#0b1ed01a40c1 fix is addressing: <PerformanceData runOrder="1" value="53650"/> <PerformanceData runOrder="1" value="22575"/> <PerformanceData runOrder="1" value="53043"/> <PerformanceData runOrder="1" value="22389"/> <PerformanceData runOrder="1" value="54680"/> The cache got repeatedly invalidated/created/invalidated/etc. My last checks in provider show a little bit of improvements in the behaviour. Hopefully you'll be able to see it too.
Comment 33 Quality Engineering 2009-04-09 19:35:35 UTC
Integrated into 'main-golden', will be available in build *200904091401* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress) Changeset: http://hg.netbeans.org/main-golden/rev/0b1ed01a40c1 User: Jaroslav Tulach <email@example.com> Log: #160390: After adding new synthetic attribute to diskProps, the system started to oscilate: Even starts were faster, odd ones slower. Ignoring and skipping this attribute shall eliminate this misbehaviour.