Bug 160390 - Empty ergonomics IDE starts more slowly than Java SE IDE (due many module dependencies)
Empty ergonomics IDE starts more slowly than Java SE IDE (due many module dep...
Status: RESOLVED FIXED
Product: platform
Classification: Unclassified
Component: Module System
6.x
Other Windows XP
: P2 (vote)
: 6.x
Assigned To: Jaroslav Tulach
issues@platform
: API_REVIEW_FAST, ERGONOMICS
Depends on: 165493
Blocks:
  Show dependency treegraph
 
Reported: 2009-03-16 17:36 UTC by Jaroslav Tulach
Modified: 2009-07-24 15:18 UTC (History)
6 users (show)

See Also:
Issue Type: DEFECT
:


Attachments
logs (85.63 KB, application/octet-stream)
2009-03-18 14:39 UTC, Oleg Khokhlov
Details
Snapshot from Linux (45.74 KB, application/octet-stream)
2009-03-22 17:12 UTC, Jaroslav Tulach
Details
Snapshot from Windows (46.99 KB, application/octet-stream)
2009-03-22 17:12 UTC, Jaroslav Tulach
Details
Speedup by deleting premature optimizations. Can this patch be applied without major compatibility problems? (1.32 KB, patch)
2009-03-24 15:00 UTC, Jaroslav Tulach
Details | Diff
Oleg, Tomáši, can you remeasure the difference with new platform10 cluster included in this ZIP please? (7.44 MB, application/x-compressed)
2009-04-03 13:06 UTC, Jaroslav Tulach
Details
The changes that improve caching - no need to parse the manifests to understand dependencies (17.77 KB, patch)
2009-04-03 13:08 UTC, Jaroslav Tulach
Details | Diff
Making Dependency serializable, caching deps for all modules (40.37 KB, patch)
2009-04-03 16:40 UTC, Jaroslav Tulach
Details | Diff
startup log from current build (20090407) (174.59 KB, text/plain)
2009-04-07 16:51 UTC, Tomas Pavek
Details
startup log from a build before the last change (20090331) (177.31 KB, text/plain)
2009-04-07 16:52 UTC, Tomas Pavek
Details
Improves what gets stored to caches so syntetic params are ignored (2.13 KB, patch)
2009-04-08 15:17 UTC, Jaroslav Tulach
Details | Diff
logs form build Apr 08 (74.34 KB, text/plain)
2009-04-08 15:34 UTC, Oleg Khokhlov
Details
logs form build Apr 08 (74.34 KB, application/octet-stream)
2009-04-08 15:34 UTC, Oleg Khokhlov
Details

Note You need to log in before you can comment on or make changes to this bug.
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 4 Oleg Khokhlov 2009-03-18 14:39:25 UTC
Created attachment 78378 [details]
logs
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 <jskrivanek@netbeans.org>
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
core-main#37fedec08173
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 <jtulach@netbeans.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
core-main#0b1ed01a40c1
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 <jtulach@netbeans.org>
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.


By use of this website, you agree to the NetBeans Policies and Terms of Use. © 2012, Oracle Corporation and/or its affiliates. Sponsored by Oracle logo