Community
Participate
Working Groups
I do some routine meaurements on editors we provide over base Eclipse, and while doing those measurements noticed, using M8, that even the basic text editor and the java editor take nearly twice as long to open on M8 than they do on the R2. 1x stream. I'll attach a file/table that shows the numbers I'm seeing. These measurements are taken with fairly large files (around 300K). The 'delta' measurements are basically just from marking time before and after a call to workbench.openEditor(...). I've done a bit of profiling with 0428 build (post M8) and noticed one thing right off. For these 300K files, there is over a million calls to String. charAt(int), traceable back to 4 calls to AbstractLineTracker.set(String). My guess is that some things are being unnecessarily initialized multiple times. That's with basic text editor and java editor. Things appear even worse for Java Editor, there's also over a million calls to JavaCodeScanner.access$0(), stemming from JavaCodeScanner$MethodNameRule. evaluate(ICharacterScanner). I know the number of calls isn't necessarily by itself a problem, I just note those as things to investigate.
Created attachment 10203 [details] Table of performance times comparing M8 to R2.1 Don't know if these tables can be interpreted out of context, but the 'value' columns give the time to open, the 'delta' columns give the increase in M8 stream (the the percent column converting that to percent of increase). The rows are called delta's just because that's the difference in 'elapsed time' since the measurements began. The rows actually represent the "occurance" after workbench started, the first taking longer, naturally, since that's the first time for certain classes to be loaded, etc. The 'count' column just lists the number of times the whole test was repeated. (One test being to open one editor, three times). Hope this helps.
I've marked as 'major' instead of 'normal' since even though absolute amounts are not great, it is a regression, and it appears in an area that would effect ALL editors built on Eclipse (which not only effects end-users, but makes it harder to do other work to improve performance measurements/improvements with other editors).
To compare apples with apples all 3.0 features should be disabled when comparing (this is especially true for the Java editor).
Please measure this during your performance pass.
Created attachment 10265 [details] measurements based on I-28 build I repeated measurements on I-28 build (instead of M8) and things look better, only a 20-30% regression instead of near 100% regression. So, thought I'd post these here just FYI. My bit of profiling though, was done on I-28 build, so those items I mentioned are probably still areas to investigate and may in fact account for substantial part of 20-30% regression?
Calls to JavaCodeScanner.access$0() removed by allowing direct access to the corresponding field in builds >20040510 David, did you disable QuickDiff during your measurements?
Increasing priority.
To answer the question, no, I did not disable quickdiff during measurements. Would that cause opening to be slower? Isn't that handled on another thread? I could see, btw, that it should be disabled while profiling 'opening', which I did not do, but my comparison measurements are taken from another program that just measures the opening. Well, now that I think about it, even my "measuring program" waits until the Display thread is "quiet", so even if quick diff mostly operates on on another thread, but busy-up's the Display thread, then it might be related. (I wait for the Display thread to be quiet intentionally, since that's when it would be ready for a user to interact with). I'll try some measurements with it off, to see if it makes a difference, but probably can't get to until later this week. And, ideally, there'd be no slow down's with default preferences, and anything which caused any slowdown would have to be requested by user. (I realize that's relative, but its always hard sell to say "yes we're slower but we're providing user with more function" ... there's no end to that if taken literally).
I was investigating the one million calls to String and agree that QuickDiff should not have much impact on the main thread. I'd appreciate if you could repeat the measurements to be sure that the effect you mention had no impact on the results.
Depends on bug 61446.
Created attachment 10743 [details] comparisons using 0514 I-build As requested, I repeated measurements with QuickDiff OFF. The good news is that the results are the same, confirming the "theory" that quick diff should not slow down opening the editor. The bad news is that the results are the same :)(that is, similar 30% ish slowdown compared to 2.1.3) These measurements were done on the 0514 build. See previous attachments for explaination of table columns and rows. I did not repeat any "profling" so have no additional info on source of problem.
Thanks David. Are you measuring with JIT enabled? Did you open any editors before starting the measurements? Is the Outline open during the measurement? I've done some measurements and analysis and am collecting different scenarios. The integration build from 0517 contains two important improvements from bug 61446 and bug 62221. I'll post my results to this or one of the upcoming builds when I've repeated my measurements.
The following are a few results from my measurements on "open Java editor" with a profiler attached to the application. Feedback and performance improvements are welcome. Setup: - builds: 2.1.3 and 3.0M9 - command: C:\eclipse\2.1.3\eclipse.exe -consolelog -showlocation -data c:\eclipse\workspaces\2.1.3 -vm c:\jdk\jdk1.4.2\bin\java -vmargs -Xrunyjpagent:port=11000,dir=C:\ymp\snapshot -Xms100M -Xmx250M (use a different workspace for 3.0) - start with an empty workspace - import org.eclipse.swt.win32 (from I200406050200) - check-out org.eclipse.swt (add org.eclipse.swt.win32 to referenced projects, add source folders in 2.1.3) - for warm-ups use: org.eclipse.swt/Eclipse SWT/win32/org/eclipse/swt/graphics/TextLayout.java (revision 1.79) - for measurements use: org.eclipse.swt/Eclipse SWT/win32/org/eclipse/swt/graphics/TextLayout.java (revision 1.27) - close all perspectives but Java (in its default configuration) and close all editors - close the Outline view - in 3.0: disable QuickDiff and Folding - restart Measurements are done by measuring the time spent in WorkbenchPage#openEditor(). Scenario 1: - warm-up: open/close 1 GC.java from Package Explorer - measurement: open 10 TextLayout.java from Package Explorer (F3) - finish: close all, restart Scenario 2: - warm-up: open/close 10 GC.java from Package Explorer (F3, Ctrl-F4) - measurement: open 10 TextLayout.java from Package Explorer (F3) - finish: close all, restart Results Scenario 1: 2.1.3: 3925ms, 4055ms, 4165ms -> mean: 4048.3ms, std dev: 98.09ms 3.0M9: 6769ms, 5648ms, 6088ms -> mean: 6168.3ms, std dev: 461.16ms 2.1.3 - 3.0M9 ratio: 1.52 Results Scenario 2: 2.1.3: 2964ms, 2974ms, 3014ms -> mean: 2984ms, std dev: 21.60ms 3.0M9: 4005ms, 3505ms, 3535ms -> mean: 3681.7ms, std dev: 396.57ms 2.1.3 - 3.0M9: 1.23 Analysis Scenario 1: (invocation count in parenthesis) 2.1.3 3.0M9 WorkbenchPage#openEditor() 4005ms (10) 6088ms (10) KeyBindingService#registerAction() 0ms (1430) 410ms (1870) TextViewer#applyTextPresentation() 60ms (10) 100ms (10) PartSite#registerContextMenu() 110ms (40) 270ms (40) MarkerAnnotationPreferences#getA*Preferences() - 160ms (30) Preferences/PreferenceForwarder#contains() 0ms (0) 60ms (5981) SourceViewerDecorationSupport#install() 60ms (10) 160ms (10) JavaEditor#setPreferenceStore() 0ms (10) 30ms (20) C*UnitDocumentProvider#createElement/FileInfo() 560ms (10) 831ms (10) SourceElementParser#parseCompilationUnit() 150ms (10) 450ms (16) Workbench#largeUpdateEnd() - 120ms (10) StyledText.ContentWidthCache#contentWidth() 80ms (340) 1001ms (310)
Christof, could you please add the proper RC target to the Target Milestone for this bug? It will help with test planning. Thanks.
As the issues are cross component issues, we can not add a target milestone other than 3.0, as long as the performance dynamic team does not have given a commitment.
David, are you using YourKit, right ? If so, which option do I use to obtain the same result you got ? "CPU" Start sampling "CPU" Start method tracing In samples I got here the tree is so large that I couldn't even find SWT on it. Please, explain the process you used to generate the list of method comparing 2.1.3 vs 3.0.
I also don't what you with: "Scenario 1: - warm-up: open/close 1 GC.java from Package Explorer - measurement: open 10 TextLayout.java from Package Explorer (F3) - finish: close all, restart" Q1. During the "warm-up", the profiler is not capturing or not ? Q2. open 10 TextLayout.java, you mean open/close (F3/Ctrl+F4) it 10 times. Q3. The profiler stops capturing before or after your perform the "finish" What confuses me is that scenario 1 and 2 are not very different (expect by the warm-up) so how come StyledText.ContentWidthCache#contentWidth() changes so much.
"I also don't what you with:" Please read: I also don't what you mean with:
I used method tracing and compared an average 2.1.3 with an average 3.0 measurement. The profiler was capturing only during the "open 10 TextLayout.java" step, where this was done by selecting 10 CUs in the package explorer and opening them all together. Closing the editors was not measured. The differences between the two scenarios may come from JIT optimizations.
Using a different profiler I get different relative numbers than those in comment 13. I now patched 2.1.3 and I200406091200 builds with a modified version of WorkbenchPage in order to measure the time spent in openEditor() with System#currentTimeMillis(). (Note that at least in 3.0 the tracing facility from Platform/UI does not measure the complete openEditor().) I used a modified (more relevant) scenario 2 from comment 13, the changes are: - no profiler attached, patched WorkbenchPage - warm-up: open 10 copies of GC.java from Package Explorer (double-click one at a time, keep open) - measurement: open copies 10 TextLayout.java from Package Explorer (double-click one at a time, keep open) - finish: close all, restart Opening one editor at a time cannot use certain optimizations that opening 10 together can use and is the more relevant case. Opening 10 editors for warm-up ensures that JIT had a reasonable warm-up phase. Having at least one editor open before starting the measurement avoids measuring additional costs of the first editor, which also is the more relevant case. Results: 2.1.3: 2914ms, 2975ms, 2905ms -> mean: 2931.33ms, std.dev.: 31.09ms I200406091200: 2924ms, 3045ms, 2943ms -> mean: 2970.67ms, std.dev.: 53.13ms ratio to 2.1.3: 1.0134 I200406091200 with Folding and QuickDiff enabled: 5368ms, 5379ms, 5378ms -> mean: 5375ms, std.dev.: 4.97ms ratio to 2.1.3: 1.83 (Note that QuickDiff does not have a big impact.)
Christof's numbers show that code folding is a significant contributor to the difference in editor opening times between 2.1.3 and 3.0. If you disable code folding, there is no regression between 2.1.3 and 3.0 using the scenario as described above. I tried a variation on this scenario using files of various sizes in both the text and java editors. Performance differences between eclpise versions due to VM changes have been avoided by using jre 1.4.2 in both cases. Also note there were no additional command line arguments passed to alter the VM default behavior. All times in milliseconds, each case run 10 times. Case 1a: Opening a Simple Text File 2.1.3 Average = 101.5 StdDev = 8.34 RC2 Average = 98.5 StaDev = 7.48 Difference = 3 RC2 is 3% faster Case 1b: Opening a large text file (contents of StyledText.java) 2.1.3 Average = 137.6 StdDev = 12.57 RC2 Average = 132.6 StdDev = 10.8 Difference = 5 RC2 is 4% faster Case 2a: Opening a simple Java class 2.1.3 Average = 197 StdDev = 7.76 RC2 Average = 268.7 StdDev = 17.98 Difference = 71.7 RC2 is 36% slower 2.1.3 Average = 197 StdDev = 7.76 RC2* Average = 226.7 StdDev = 10.98 * In this scenario QuickDiff and Folding have been disabled Difference = 29.7 RC2 is 15% slower Case 2b: Opening a medium sized Java Class (TableCursor) 2.1.3 Average = 261.2 StdDev 7.72 RC2 Average = 333.0 StdDev = 10.54 Difference = 71.8 RC2 is 27% slower 2.1.3 Average = 261.2 StdDev 7.72 RC2* Average = 286.0 StdDev = 10.54 * In this scenario QuickDiff and Folding have been disabled Difference = 24.8 RC2 is 9% slower Case 2c: Opening a large Java Class (StyledText) 2.1.3 Average = 860.9 StdDev = 120.23 RC2 Average = 1787.5 StdDev = 33.94 Difference = 926.6 RC2 = 108% slower 2.1.3 Average = 860.9 StdDev = 120.23 RC2* Average = 715.4 StdDev = 178.53 * In this scenario QuickDiff and Folding have been disabled Difference = 145.5 RC2 = 17% faster
Note that using the system clock requires that no background activity runs during the measurement. The relatively big std.dev. for opening StyledText in the JavaEditor may indicate that the reconciling thread from the previous editor was still running when the measurement for the next editor was started.
Fix available in 3.0RC2
started verifying...
Verified on MacOS X (1.25GHz PB) average of opening StyledText.java 10 times: 2.1.3: 5.6 s 3.0 w/o folding: 3.0 s 3.0 w folding: 5.0 s Cool!
