Community
Participate
Working Groups
The current 4.2 startup time as measured by the UIStartupTest is about double of that of 3.8. We do more work on the startup, such as loading EMF model and EMF classes, and performing consolidation between 3.x and 4.x objects so this is not totally unreasonable. Yet, it would be nice to see if we can improve.
When looking at profiler results for the startup, one area that stands out is the model loading and assembling. The loading EMF models and processing deltas takes somewhere on the order of 25% of the startup time with model assembling adding another 5%. That seemed like a good target so I run some preliminary tests saving and loading full model. While I did observe about 10% improvement in startup time, the gain was lower then expected. It turns out that: 1) loading EMF model is expensive. At the time my workbench.xmi file was about 2Mb and loading it was taking 1.8 sec on my computer, or 16% of the startup time. 2) we "leak" model elements - on every startup/shutdown workbench.xmi grows, starting from about 300K and adding about 80K every cycle. === For (1) I am not sure what we can do (other than switching to binary file?) I tried adding setIntrinsicIDToEObjectMap to E4XMIResource but that only made loading time worse. Seems we already have E4XMIResource#objectMap, does it perform the same duty? I also tried running combinations of different options: OPTION_DEFER_IDREF_RESOLUTION OPTION_USE_PARSER_POOL OPTION_USE_XML_NAME_TO_FEATURE_MAP OPTION_DEFER_ATTACHMENT OPTION_USE_DEPRECATED_METHODS The options did not seem to produce any significant change. === For (2) it seems that we leak descriptors and bindings. I'll check to see if we can fix that. === Another potential area of improvement would be to keep and re-use modeled menus and toolbars between startups.
Ed - any ideas from your side?
How much of the time is loading verses processing deltas. Certainly binary resources are dramatically smaller and faster, but not being human readable seem bad...
(In reply to comment #3) > How much of the time is loading verses processing deltas. Good question, here is some raw data: On a nearly clean workspace (clean workspace + "hello world" plugin + one extra stack with a view): Using deltas: % of model loading % of startup time (2500 ms) time (11,000 ms) Base model load time: 90 ms 4% 1% Model assembler run time: 500 ms 20% 5% Load and process deltas: 1700 ms 70% 15% Not using deltas: % of model loading % of startup time (1200 ms) time (10,000 ms) Complete model load time: 450 ms 40% 5% Model assember run time: 540 ms 45% 5%
Discussion of the raw numbers above: For the case of using deltas, loading base model is a non-issue, but loading and processing deltas takes 1.7 sec or 15% of the total startup time. (The delta size for those numbers is about 400K.) Using complete model saved on the last run, it takes ~0.5 sec to load the model containing ~450K. As the model size and delta size grows, the processing time goes up. A very rough estimate of the growth rate is about 1ms/kB for deltas and 0.5ms/kB for complete model loading.
Is a lot of time spent in ResourceImpl.getEObjectByID? XMIResourceImpl does maintain two way maps between EObject and their IDs for extrinsic IDs (i.e., for xmi:id). If there is a specialized implementation that's also maintaining a map, using that map for looking up the object by ID is likely to be helpful.
*** Bug 379601 has been marked as a duplicate of this bug. ***
(In reply to comment #4) > (In reply to comment #3) > > How much of the time is loading verses processing deltas. > > Good question, here is some raw data: [snip] I would be interesting to know how these numbers change, e.g. if add another 9 hellow world plugins + 9 views and even 99 plugins + views.
Think the severity should be higher- this is a major regression in start - up time (doubled) which is further exacerbated by consuming products.
Interesting point: 4.2 with new workspace (Welcome page shown) is FASTER than 3.8. However, when I only add a single Java project, it starts 30-50% slower on 4.2.
*** Bug 391365 has been marked as a duplicate of this bug. ***
Based on the changes to ResourceHandler, for this bugzilla, can I correctly assume there is no longer a way to generate the deltas instead of saving the entire model? I ask b/c I have the following use case and was planning on using the deltas to fulfill it: Deploy RCP app to desktop and save the deltas, per user, in a remote location. Allow upgrade of installed app with additional updates to the model. Merge the new changes with the modifications the user has already made (to the model). Is there another way to achieve this perhaps? Or should I just plan to use the ModelReconciler myself (I assume it's in a usable state)? -sean
we are not using the delta approach anymore but your can replace the model saving/loading yourself.
*** Bug 408170 has been marked as a duplicate of this bug. ***
(In reply to comment #14) > *** Bug 408170 has been marked as a duplicate of this bug. *** See bug 408170 comment 1 for a hint of a possible performance bottle neck.
From the trace in https://bugs.eclipse.org/bugs/show_bug.cgi?id=408170, it seems clear from the trace that the previous suggestions I've made haven't been properly investigated. From the trace it's clear that 77% of the time is spent in ResourceImpl.getEObjectByID where it's repeatedly walking the entire tree once for each ID lookup, so I find it hard to believe that adding a map using org.eclipse.emf.ecore.resource.impl.ResourceImpl.setIntrinsicIDToEObjectMap(Map<String, EObject>) when creating the resource in the resource factory would make things slower. Certainly a map lookup couldn't be slower than walk the whole tree. Something else must have been going on... Using org.eclipse.emf.ecore.xmi.XMLResource.OPTION_DEFER_IDREF_RESOLUTION for loading should reduce this cost from 77% to neglible, because in combination with these two changes, a single traversal of the resource would be needed to populate the map and then all subsequent lookups use the map. Please try again and use the debugger (or profiler) to confirm the behavior you'd hope to see in getEObjectByID.
One thing that I noticed is that start times for running as a runtime workbench are quite different. I'll profile that as well and attach what I find.
Created attachment 231107 [details] Profile of startup for 4.2.2 SDK Mac 64 bit Here's a yourkit profile of the startup of 4.2.2. Not much different than 4.3.M6, which is attached to Bug 408170. I am getting a startup time of 22s-24s with an empty workspace.
And I was wrong in comment #17, startup times for the runtime workbench are the same as for regular launch.
And here too 28% of the total start up time is due to the 771 calls to getEObjectByID, each one apparently iterating over on average 2,000 objects in the content tree of the resource. Of the 31% of the time needed to load the one resource, the vast majority of that time is spent resolving the IDs so it looks like there's room for at least a 25% improvement in startup time if this cost can be reduce to 771 map lookups and just a single traversal of the tree.
Created attachment 231116 [details] Startup time e4.3 M6 with Ed's suggested change I made the change that Ed suggested and took a new snapshot. The model time load is indeed much smaller, but surprisingly the overall startup time has remained about the same. Now, there is no longer a single hotspot. The bottlenecks are more spread throughout the startup. Anyone else with more experience here able to provide some insight?
From the profiler trace, it looks like the main has gone from 9.1 seconds down to 8.4 seconds, and the "all threads" has gone from 12.4 seconds to 10.7, so that's a significant improvement but not overly dramatic. Looking at the method list loadClass comes in at 50% of the overall time. I'm not sure there's much that can be done to improve that, other than load fewer classes, but that's easier said than done. During loading of the resource ContextInjectionFactory.invoke is called 7 times and that takes of 34% of the remaining model load time; class loading take 25% of the model load time (though those two things likely overlap). When you start to dig deeper down most of the call stacks that look expensive, you typically end up finding class loading being a dominant cost... Creating the display takes 11% of the time with the one call to NSThread.isMainThread being 2/3 of that time. What's it doing that's so expensive? I'm not sure how much threading is involved at startup. It might be the case that if a thread is spawned early to eagerly load classes that are needed later that more could be done in parallel...
Given that by default dropins is enabled, and it would just load classes to figure that there is nothing (at least in most case), I'm thinking that save some time by disabling it out of the box and making it an option that people have to enable.
That's a good idea, but in my experience, the people who use dropins the most are often the least sophisticated users, who wouldn't know to turn on the setting (and might complain loudly on some mailing list). A suggestion would be the following. Since the dropins directory will typically be empty, unless someone has added some plugins there, could you first check the filesystem to see if there are any files that look like plugins (or just check to see if it is non-empty). And only then start loading the dropins support. There must be other places like this where we can save on startup time. We have already made changes in many of our (non-Eclipse foundation) projects to be more careful about startup costs and it has paid off, but there is still some work to do.
Are there any plans to work on this bug for the Kepler release? I was expecting and hoping that e4.3 would have a shorter start time than e4.2 since all the performance improvement bugs were marked as fixed. Is this not considered a high priority bug? I'm happy to do more profiling and testing, but not being familiar with EMF or e4, it will be hard for me to submit a patch that really fixes the issue without some more guidance.
We are essentially done with Kepler development at this point with the exception of documentation and severe bugs. All of the focus on performance work was done in the 4.2.2 timeframe so I wouldn't expect much improvement between 4.2.2 and 4.3. It should be noted for people just coming to this bug that most of the comments prior to May 2013 are stale. There have been a lot of changes since Oleg's initial investigation and his numbers are no longer useful. As measured by -debug command line argument I am currently seeing 7 seconds to start an empty workbench on I20130526-2000, vs 6 seconds for 3.7.2. So there is certainly room for improvement here but it's unlikely there is a smoking gun that will lead to significant further gains. I don't think the dropins stuff will make much difference. That code was very heavily optimized and it is reduced to a timestamp check directly in the Activator#start for the case where nothing has changed since last run. Unless we see profile data where this comes up as a bottleneck I don't think it's worth pursuing.
Thanks for the response, John. What kind of profiling data would you be looking for? As I mentioned, I am seeing start times for e4.3 and e4.2.2 much higher than the start times of e3.7. The yourkit profiles are already attached. I fully admit that I am not being particularly rigorous about profiling (I am doing this on my local machine with a bunch of other stuff running), but these times are roughly repeatable and there is a significant difference between the 3.x stream and the 4.x stream. I am happy to provide more data if this is what you need.
Given the trivial localized nature of the changes (resource loading options) it might be nice to confirm the performance improvements run all the tests to see if it's worth providing such improvements for the current release...
I opened bug 409279 to track the EMF load options. I have pushed a patch to Gerrit there, for which I would appreciate comments. On my machine, the average model load time drops from ~1200 ms to around ~400 ms, which is certainly significant in itself. But, total start-up time is still in the 5-6 second range, so I'm not sure that this is noticeable.
There is definitely some problem in E4XMIResource.createId(): it uses "objectMap.values().contains(...)". So there is a N^2 hidden here. We encountered the same problem when migrating our application to E4: start time (after workspace dialog) went up from 10 -> 30 seconds. After patching the above class by adding an additional HashMap to store the ids the startup time is more in the range of 15s. Still slower than before but acceptable for now.
(In reply to comment #30) > There is definitely some problem in E4XMIResource.createId(): it uses > "objectMap.values().contains(...)". So there is a N^2 hidden here. > > We encountered the same problem when migrating our application to E4: start time > (after workspace dialog) went up from 10 -> 30 seconds. After patching the above > class by adding an additional HashMap to store the ids the startup time is more > in the range of 15s. Still slower than before but acceptable for now. I have confirmed that this is non-linear, and have pushed a fix to Gerrit (for master/4.4). But, I'm not seeing anywhere near 15-20s improvements on the size of models I have (~2500 elements) - more like 1s. I suspect the changes for bug 409279 account for the remaining improvement. Christian: what version of Eclipse was your app built upon? https://git.eclipse.org/r/17008
Thanks for the fix. Helps us a lot. We are using Eclipse 4.4.0. After your comment I rechecked our application and can confirm that we indeed have included a third party component that creates so many menus and expressions that it uses approx. 24.000 ids alone. If I disable this component the number of ids used goes down to approx. 6000. Whole Eclipse Platform (Automotive Distribution) for us is approx. 3800. So this is why we loose 15-20 seconds here, but I agree that this fix will only help for very large products.
(In reply to Paul Elder from comment #31) > > https://git.eclipse.org/r/17008 I've released this fix for master. Thanks Paul. Our UITestSuite is an edgecase (not a normal usage pattern) but it reduce the running time on my machine from about 260s to 130s. I'd include it for that improvement alone! :-) PW
Is their something left to do in this bug, or can we close it?
(In reply to Lars Vogel from comment #34) > Is their something left to do in this bug, or can we close it? We should measure current start up time and compare against 3.8.2 and then decide whether this is good enough.
(In reply to Dani Megert from comment #35) > (In reply to Lars Vogel from comment #34) > > Is their something left to do in this bug, or can we close it? > > We should measure current start up time and compare against 3.8.2 and then > decide whether this is good enough. I've been doing that this week with the performance tests. What I'm seeing so far with the UIApplicationStartup test is: 3.8.2: 5.686 - 5.807 ms (95% confidence) 4.3.1: 8.450 - 8.578 ms (95% confidence) 4.4M5: 9.701 - 9.824 ms (95% confidence) Each of these is based on 100 runs on the same machine with the same JVM (an IBM 1.6 64-bit JVM) on Windows 7 (64-bit) I am just now starting to profile these in detail. Observations so far: * both 4.3.1 and 4.4M5 spend about 2/3 of their time in class loading. (Haven't profiled 3.8.2 yet). * 4.4M5 loads ~8800 classes while 4.3.1 loaded 8500 (3.5% increase) * 4.4M5 spends about 300ms more time in the class loader than 4.3.1 (~7% increase), and about 800ms more in the call graphs beneath the class loader (~12% increase) I have a lot more digging to do, but one thing I want to look at is whether the changes to Equinox that appeared in 4.4 are having an impact.
(In reply to Paul Elder from comment #36) > Each of these is based on 100 runs on the same machine with the same JVM (an > IBM 1.6 64-bit JVM) on Windows 7 (64-bit) > > I am just now starting to profile these in detail. Observations so far: > * both 4.3.1 and 4.4M5 spend about 2/3 of their time in class loading. > (Haven't profiled 3.8.2 yet). > * 4.4M5 loads ~8800 classes while 4.3.1 loaded 8500 (3.5% increase) > * 4.4M5 spends about 300ms more time in the class loader than 4.3.1 (~7% > increase), and about 800ms more in the call graphs beneath the class loader > (~12% increase) > I'm confused by the call graphs statement. This time is not considered part of class loader time? How do you separate the two? > I have a lot more digging to do, but one thing I want to look at is whether > the changes to Equinox that appeared in 4.4 are having an impact. It certainly is possible that the Equinox changes need some optimization here. Off the top of my head I am not sure what would contribute to the increase for the overall search path to locate class bytes and define them. There are certainly some more generic data structures used to determine the class loader wiring, but once these are established the overall path to locate a class should be approximately the same as previous releases.
> both 4.3.1 and 4.4M5 spend about 2/3 of their time in class loading. The other thing to consider is that during classloading, the start methods of the plugins are invoked.
(In reply to Thomas Watson from comment #37) > I'm confused by the call graphs statement. This time is not considered part > of class loader time? How do you separate the two? I seem to have been misinterpreting what YourKit is trying telling me. In the CPU/Method view, I see two time columns: 'Time' and 'Own Time'. The doc is ambiguous/confusing. The YourKit forums seem to indicate that 'Own Time' is the time spent in the method itself, but not in the methods it calls, while 'Time' is the total time in the method and all its callees. But, then I see values like this in the results (from a 4.3.1 run): Method Time Own Time ------ ---- -------- java.lang.ClassLoader.loadClass(String) 4399 6286 In all my results, loadClass's 'Own Time' is substantially larger than it's 'Time'. I don't see how this can possibly be correct. So, I'm going to have to treat 'Own Time' as unreliable. For 4.4M5, the top entries in the CPU/methods list based on Time are (Own Time is included, as the second number in each line): org.eclipse.core.launcher.Main.main(String[]) 9099 9005 java.lang.ClassLoader.loadClass(String) 4699 7086 org.eclipse.core.internal.jobs.Worker.run() 764 764 org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run() 624 358 org.osgi.util.tracker.AbstractTracked.trackAdding(Object, Object) 343 0 org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceReference, ServiceEvent) 327 0 org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(Object, Object) 327 0 ... (lots more entries with insignificant times) It seems clear that class loading is a big factor even if I cannot trust 'Own Time'. I'm going to try some different YourKit configurations, to see if I can get more details on class loading itself. I may also try some 'tracing' rather than just 'sampling', to see if that gives me better resolution. Let me know if you want me to attach the YourKit results.
Created attachment 239493 [details] 3.8.2 Hotspots from Yourkit 'trace' Hotspots in 3.8.2 as identified by YourKit. Options: * tracing * onexit==snapshot * builtinprobes==all Attached as a base for comparison with 4.3.1 and 4.4M5
Created attachment 239494 [details] 4.3.1 Hotspots from YourKit 'trace' Hotspots in 4.3.1 as identified by YourKit. Options: * tracing * onexit==snapshot * builtinprobes==all Attached as a base for comparison with 4.4M5
Created attachment 239495 [details] 4.4M5 Hotspots from Yourkit 'trace' Hotspots in 4.4M5 as identified by YourKit. Options: * tracing * onexit==snapshot * builtinprobes==all
A few notes on the attached 'hotspot' reports: 1) 4.4M5 includes more hotspots that either 3.8.2 or 4.3.1 2) Most seem to be in Equinox areas: BundleLoader and ServiceTracker stand out. 3) There are 8000+ new File(File, String) object creations in 4.4M5 that don't appear in either 3.8.2 or 4.3.1 Tom: I don't understand what's going on inside Equinox. Is there more information I can provide?
(In reply to Paul Elder from comment #43) > A few notes on the attached 'hotspot' reports: > 1) 4.4M5 includes more hotspots that either 3.8.2 or 4.3.1 > 2) Most seem to be in Equinox areas: BundleLoader org.eclipse.osgi.container.ModuleWiring.getRequiredModuleWires(String)","455","41219 I think I can fix this by caching the required bundle wires for each BundleLoader org.eclipse.osgi.internal.loader.BundleLoader.addExportedProvidersFor(String, List, Collection)","1048","41675 I'm not sure why this is getting called so much more for this release than previous releases. Is this just taking longer so it shows up in the hotspot? Perhaps in previous releases it gets called the same amount of times, but is just so much faster that it does not show up as a hotspot? > and ServiceTracker stand out. ServiceTracker seems the same between 4.3.1 and 4.4M5. I know e4 makes more use of services than previous releases of the workbench. The ServiceTracker implementation is pretty much unchanged between the releases so I just suspect more code is using a ServiceTracker. > 3) There are 8000+ new File(File, String) object creations in 4.4M5 that > don't appear in either 3.8.2 or 4.3.1 I'm not sure what is calling new File(..) so many times. I would be surprised if it is the framework (famous last words). Is there any way to tell who is making these calls? > > Tom: I don't understand what's going on inside Equinox. Is there more > information I can provide?
(In reply to Thomas Watson from comment #44) > org.eclipse.osgi.container.ModuleWiring.getRequiredModuleWires(String)", > "455","41219 > > I think I can fix this by caching the required bundle wires for each > BundleLoader > Opened bug 427055 for this.
(In reply to Thomas Watson from comment #44) > org.eclipse.osgi.internal.loader.BundleLoader.addExportedProvidersFor(String, > List, Collection)","1048","41675 > > I'm not sure why this is getting called so much more for this release than > previous releases. Is this just taking longer so it shows up in the > hotspot? Perhaps in previous releases it gets called the same amount of > times, but is just so much faster that it does not show up as a hotspot? > I opened bug 427056 to do some more possible optimizations for calculating reexported packages.
Good findings Paul!
(In reply to Thomas Watson from comment #45) > (In reply to Thomas Watson from comment #44) > > > org.eclipse.osgi.container.ModuleWiring.getRequiredModuleWires(String)", > > "455","41219 > > > > I think I can fix this by caching the required bundle wires for each > > BundleLoader > > > > Opened bug 427055 for this. In my testing I don't marked improvements with this fix. It seems to reduce the time spent in BundleLoader by < 5% More savings is seen in the fix I am working on for bug 427056. Where I saw a reduction of time spent in BundleLoader by %50
(In reply to Thomas Watson from comment #48) > (In reply to Thomas Watson from comment #45) > > (In reply to Thomas Watson from comment #44) > > > > > org.eclipse.osgi.container.ModuleWiring.getRequiredModuleWires(String)", > > > "455","41219 > > > > > > I think I can fix this by caching the required bundle wires for each > > > BundleLoader > > > > > > > Opened bug 427055 for this. > > In my testing I don't marked improvements with this fix. It seems to reduce > the time spent in BundleLoader by < 5% > > More savings is seen in the fix I am working on for bug 427056. Where I saw > a reduction of time spent in BundleLoader by %50 Re-ran the perf tests with the N20140201 nightly build. There is a measurable improvement over the number in comment 36: 3.8.2: 5.686 - 5.807 s (95% confidence) 4.3.1: 8.450 - 8.578 s (95% confidence) 4.4M5: 9.701 - 9.824 s (95% confidence) N20140201: 9.336 - 9.428 s (95% confidence) That's about 400ms better, but still about 900ms higher than 4.3.1. I'll re-run the profiles, too, and report any changes in hot spots. (Note, my previous numbers in comment 36 incorrectly expressed seconds as milliseconds.)
(In reply to Paul Elder from comment #49) > Re-ran the perf tests with the N20140201 nightly build. There is a > measurable improvement over the number in comment 36: > > 3.8.2: 5.686 - 5.807 s (95% confidence) > 4.3.1: 8.450 - 8.578 s (95% confidence) > 4.4M5: 9.701 - 9.824 s (95% confidence) > > N20140201: 9.336 - 9.428 s (95% confidence) > > That's about 400ms better, but still about 900ms higher than 4.3.1. I'll > re-run the profiles, too, and report any changes in hot spots. > > (Note, my previous numbers in comment 36 incorrectly expressed seconds as > milliseconds.) 1. I wonder, if measuring these times could be integrated into the build process? Doing it manually is fine for an adhoc comparison, but as this ticket ripples through every release, a graph of the progress (positive or negative) over time might emphasize the importance. 2. Nevertheless, as there are no better numbers available, may I ask you Paul again, to please measure a recent 4.5 build on your dedicated hardware to keep comparable? Thanks! Sadly it seems at least one of us got a save job for the foreseeable future here ... 3. Also I question if there is any moment in time when striving for performance is good enough to close this ticket? So what criteria have to be met? a) Should 4.x become faster than 3.8.2 in Pauls manual benchmark? b) Are we keeping this around until Eclipse 5.0 to open a successor of this? c) Are we hoping, Moores law will mitigate this into oblivion? I really tried hard to take the sarcasm out ... but I'm sad still, so I might not have excelled ... sorry
(In reply to Holger Klene from comment #50) Once we have identified all notable performance issues, we will create separate bugs for them and close this bug. Running performance test on a regular basis is topic of Bug 374441.
Opened Bug 461828 for a performance regression in Equinox with lots of re-exports. I mark this one as fixed and we open new bug reports for additional performance problems.
Nothing to verify, we have new bugs for outstanding performance issues
