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: | Opening JSP is slow | ||
---|---|---|---|
Product: | javaee | Reporter: | L Martinek <lmartinek> |
Component: | JSP | Assignee: | Marek Fukala <mfukala> |
Status: | VERIFIED FIXED | ||
Severity: | blocker | CC: | dkonecny, dpavlica, issues, jrojcek, pjiricka, tmysik, tprochazka |
Priority: | P2 | Keywords: | PERFORMANCE |
Version: | 4.x | ||
Hardware: | All | ||
OS: | All | ||
Issue Type: | DEFECT | Exception Reporter: | |
Bug Depends on: | 52017, 67305 | ||
Bug Blocks: | 70094 | ||
Attachments: |
The JProfiler CPU view output for the JSP file opening.
The JProfiler CPU view output for the JSP file opening. web/jspparser diff for the encoding parser The JSP encoding parser subsequent usage of jsp file |
Description
L Martinek
2004-07-08 15:16:02 UTC
I would say it is caused by the heavy activity during the JSP page parsing - reassigning. fixed (partially) Now the JSP page analyse done by tomcat's parser is postponed after the editor is shown, so the user can see the editor faster, the taglibs colorig shows after the page is analyzed. For common JSPs it can be about 100ms, for huge ones it can take about 2 seconds. One additional thing done is that the opened page encoding is not obtained from the tomcat parser twice, but only one. The parsing for the encoding itself is very demanding and should be optimized as well. [on my computer the JSP page first opening is more than two times faster - from 4600ms to 2200ms. Size of the page is about 600kB] Please reopen this bug if the performance still doesn't meet the given criteria. Checking in BaseJspEditorSupport.java; /cvs/web/core/src/org/netbeans/modules/web/core/jsploader/BaseJspEditorSupport.java,v <-- BaseJspEditorSupport.java new revision: 1.38; previous revision: 1.37 done Checking in TagLibParseSupport.java; /cvs/web/core/src/org/netbeans/modules/web/core/jsploader/TagLibParseSupport.java,v <-- TagLibParseSupport.java new revision: 1.27; previous revision: 1.26 done an additional fix for this issue. Now JSP pages without taglibs should be opened faster - the editor doesn't repaint the document content after parsing of the page is finished. Checking in JSPColoringData.java; /cvs/web/jspsyntax/src/org/netbeans/modules/web/core/syntax/spi/JSPColoringData.java,v <-- JSPColoringData.java new revision: 1.4; previous revision: 1.3 done http://web.netbeans.org/source/browse/web/jspsyntax/src/org/netbeans/modules/web/core/syntax/spi/JSPColoringData.java.diff?r1=1.3&r2=1.4 Reopening. It still lasts about 2 sec. OK, now reopening. Fixed the JSP page encoding problem. It is a replacement for a wrong fix (which caused Issue #48456) reverted by a revision 1.39 Checking in BaseJspEditorSupport.java; /cvs/web/core/src/org/netbeans/modules/web/core/jsploader/BaseJspEditorSupport.java,v <-- BaseJspEditorSupport.java new revision: 1.40; previous revision: 1.39 done According to the performance tests results and in direct comparison with java file opening the times for opening JSPs are shorter (~2000ms vs 3000ms for java). Now I do not see any further way how to easily and safely improve the performance -> setting TM to next release. Opening Java file is first test executed in IDE so it also includes initialization of editor and other stuffs. It's better to compare opening JSP with opening Servlet file, which takes about 1 s. Are there any reasonable performance test results for this case now? There has been a plenty of fixes which could potentially affect this problem. Please attach any relevant data or send me a test otherwise I will close this bug since no *real* user complains about it. We are measuring next numbers : ( RHE Linux 3 JDS 2 Solaris 9 Solaris 10 Win 2000 Win XP ) 1st usage 1558 1342 2046 1923 1161 1854 Subsequent usage 477 429 597 476 445 441 for test case look at the page: http://performance.netbeans.org/qa/Performance.html#measure_actions OK, I see. My personal opinion on that is that in the context of all what needs to be done when a JSP is opening - especially parsing the webapp - the times are quite acceptable. I would like to hear Karel's or Jiri's opinion on that. However, I must say, there is almost no chance to improve the times significantly now. According to early results from performance survey that is running in NetCAT 4.1 now, people don't see any UI performance issues in webapps. Only one guy complained about slow Java code completion in scriplets. In my opinion, fixes done to date are sufficient. I recommend to get the opening time into boundary of 1 sec for next release. I don't agree with closing this issue as fixed, though. I do not want to close this isses as fixed neither ;-). I only wanted to hear your opinions on the priority and severity of this issue. I definitively agree with improving the opening time somehow though I do not see an easy way now. So if you don't mind I will try to fix it in next release. I understand there are more severe bugs waiting for resolution now. Having said that I am okay with full fix going to the next release. OK - setting the TM to next release. I will do the some for Issue #45936. After few probes w/ Marek we agreed to raise this to P2 again. Especially the first open is pain. Some minor notes about next open - JspParserImpl.getJspOpenInfo seems to be called twice during open doing probably the same job. - commons-logging: building of various logger takes time as it always tries to load a resource from default package + reflection to find context class loader. perhaps we can set logger factories/impls directory to avid various reflections and attempts to load resources/classes here, might be interesting to patch ProxyClassLoader to check how often it fails (once/for every JSP/for every logger) one particular problem can be slow EncodingUtil.detectEncoding() in XML API (lot of classloading + I/O according to what I saw) in my profiler JSP parsing is started earlier than painting of editor is finished (slow machine + profiler overhead can be the reason) Parsing takes a lot of time - one noticeable hot spot is o.a.j.c.TldLocationsCache.getUriFromTld where DOM document is created. I am afraid that it also validates the XML file. Radim, do you think this is slower than in NetBeans 4.1? Thanks. Petre, the JSP file opening is significantly slower than in 4.1. I tried to investigate it and found same interesting facts: 1) the mechanism of jsp page/web project parsing which was run after the JSP file is opened (text visible in the editor) doesn't work now from not yet known reason. This is one of the most significant regression. 2) the JSP palette is initialized during the document opening. I have already talked about it with Libor and I belive I know how to fix it once I start working on this issue. 3) it seems that the web.xml model is created during the file opening. I haven't investiagted this yet, but AFAIK this is not necessary and should be resolved somehow as well. So we really need to fix this issue to 5.0. The first JSP opening time is terribly long (about 6-8 seconds on my machine)!!! 4) The JspFoldManager.initFolds() creates a new TimerTask and schedules it to be run after 2000ms. So because the opening of the file is definitively slower than the limit, the folding creation code is also run during the file opening. I will use the same way as JSP parsing uses (currently not working), so the folding code will be run after the file is rendered in the editor. I have integrated some partial fixes to this area: 1) the "jsp page autoparse" is not peformed when the file is newly opened in the editor (the file parse is already done from another code) 2) the jsp parser is now run when TC.componentActivated is called 3) the JSP palette initialization (adding of the palette into TC lookup) is also done when TC.componentActivated is called 4) BaseJspEditor.isXMLSyntax() now uses data from cached openinfo Checking in src/org/netbeans/modules/web/core/jsploader/BaseJspEditorSupport.java; /cvs/web/core/src/org/netbeans/modules/web/core/jsploader/BaseJspEditorSupport.java,v <-- BaseJspEditorSupport.java new revision: 1.54; previous revision: 1.53 done Checking in src/org/netbeans/modules/web/core/jsploader/TagLibParseSupport.java; /cvs/web/core/src/org/netbeans/modules/web/core/jsploader/TagLibParseSupport.java,v <-- TagLibParseSupport.java new revision: 1.44; previous revision: 1.43 done I will attach an output from jprofiler which clearly states that about 25% of the JSP file opening runs in "editor options/mime lookup code". Another 15% is spent in toolbar initialization. I think these two groups of code hotspots are the major causes of the regression and should be solved IMHO on the options/editor side. Created attachment 26495 [details]
The JProfiler CPU view output for the JSP file opening.
I have measured the opening once more and here is my summary: 1) the biggest problem of the JSP file is the encoding determination during the file opening. There is various ways of how to set JSP files encoding (the file, deployment descriptor). It is necessary to use tomcat parser to resolve this. The parser first loading and run is very time consuming it takes about 20% of the opening time. * I do see two possible solutions here: a) create own fast parser for JSP encoding and for the deployment descriptor (very time consuming tasks [~1week], possibly many regressions) b) initialize the parser during web project opening (will slow down also the IDE startup time) 2) parsing of the JSP page (necessary for proper custom tags coloring and CC) is done after the page is visible (at least after TC.componentActivated is called). 3) JSP palette initialization is also postponed after the TC becomes active 4) the biggest consumers of the opening time are: a) toolbar initialization (~20%) b) settings loading (~20%) c) mimelookup initialization (~8%) I am also attaching a new Jprofiler memory view for the JSP opening Created attachment 26617 [details]
The JProfiler CPU view output for the JSP file opening.
I have prepared some fixed for this issue: 1) The JSP editor is now lookuping and initializing editor setting, mimetype, editor kit etc. in a warm up task JspEditorWarmUpTask. The task is performed only when there is at least one opened web project in the IDE so it doesn't slow down users who don't use web features. 2) I have implemented a lightweight fast jsp encoding parser which works for JSPs which lies in a webmodule which deployment descriptor doesn't defines JSP groups encoding (I would say 99% of all JSPs). For more information see javadoc of FastOpenInfoParser class (I will attach a diff). According my measurements using two fixes along with the ones commited before the opening time is about 1200ms in comparison with 2700ms before. On the qa-sol9-perf machine the times are now about 2700ms in comparison to ~6000ms before. Since the fix is not trivial I am attaching a diff first and kindly asking at least Petr Pisl to check it. I have also asked Jirka Proxa to test a custom build. Created attachment 26682 [details]
web/jspparser diff for the encoding parser
Created attachment 26683 [details]
The JSP encoding parser
Marek, I looked through your proposed patch and it's very promising. After applying this we can fix more jsp encoding bugs, outside a web module or in web module, which doesn't have a deployment descriptor. Great:). There are my notices: 1) FastOpenInfoParser - is not able to obtain encoding for jsp document (jsp pages in xml syntax) 2) FastOpenInfoParser - the constructor has the parameter WebModule. We should have the result even for pages, which are outside a web module, so it will be very useful, when we can put here null and we will be still able obtain the encoding of a jsp page. There is not any obstacle to do it. 3) FastOpenInfoParser is called only, when there is not defined an encoding for a jsp-property-group in the deployment descriptor. So in the case when there is at least one encoding defined in the deployment descri I have just commited the patch with some other improvemenets (handling of JSPs encoding outside of webmodule, JSP XML document encoding detection etc.). We will see whether it will help to get the numbers down... RCS file: /cvs/web/core/src/org/netbeans/modules/web/core/JspEditorWarmUpTask.java,v done Checking in web/core/src/org/netbeans/modules/web/core/JspEditorWarmUpTask.java; /cvs/web/core/src/org/netbeans/modules/web/core/JspEditorWarmUpTask.java,v <-- JspEditorWarmUpTask.java initial revision: 1.1 done Checking in web/core/src/org/netbeans/modules/web/core/resources/layer.xml; /cvs/web/core/src/org/netbeans/modules/web/core/resources/layer.xml,v <-- layer.xml new revision: 1.83; previous revision: 1.82 done Checking in web/jspparser/nbproject/project.xml; /cvs/web/jspparser/nbproject/project.xml,v <-- project.xml new revision: 1.10; previous revision: 1.9 done RCS file: /cvs/web/jspparser/src/org/netbeans/modules/web/jspparser/FastOpenInfoParser.java,v done Checking in web/jspparser/src/org/netbeans/modules/web/jspparser/FastOpenInfoParser.java; /cvs/web/jspparser/src/org/netbeans/modules/web/jspparser/FastOpenInfoParser.java,v <-- FastOpenInfoParser.java initial revision: 1.1 done Checking in web/jspparser/src/org/netbeans/modules/web/jspparser/JspParserImpl.java; /cvs/web/jspparser/src/org/netbeans/modules/web/jspparser/JspParserImpl.java,v <-- JspParserImpl.java new revision: 1.29; previous revision: 1.28 done Checking in ide/golden/deps.txt; /cvs/ide/golden/deps.txt,v <-- deps.txt new revision: 1.243; previous revision: 1.242 done The performance test results do not look too much promising. The opening times dropped only a little (current time is ~5.5 - 6.0 sec) though according to manual measurement (a human with stopwatches) gives times around 4 seconds (3700-4300 for several measurements). The manually measured times before the patch was 7000-8500 ms. So the question is whether the test works properly. Martine, can you verify it please? On my linux notebook the first opening times of JSPs dropped from about 2200ms to 1000ms which is almost 60% improvement. Similar results are measured on test machines (7000-8500 to 3700-4300) which is also around 50% improvement. Since we are still far away of 1000ms and I must say I do not have to time play with this issue another few days and I am also out of ideas a little, I will likely ask for a waiver for this issue :-(. The improvements done recently are really measureable in our tests. The subsequent invocation times are <1s and the 1st invocation times dropped to Open JSP file [ ms ] / 1000 ms FC3 Sol9 Sol10 WinXP 1st usage 3309 3747 3558 1682 Subsequent usage 844 757 664 N/A This state should be further improved with upcomming fix of issue 52017. Thus keeping this issue open (the times are not <2s and most probably will not be after the fix of the above issue), but decreasing to P3 for now. After the fix of issue 52017, the tests show improvement in most of the numbers measured for JSP file opening: Open JSP file [ ms ] / 1000 ms FC3 Sol9 Sol10 W2K WinXP 1st usage 2935 3128 3379 1734 1687 Subsequent usage 770 584 577 N/A N/A Closing as fixed for 5.0. Thanks to all who made the improvements! After the fix of issue 52017, the tests show improvement in most of the numbers measured for JSP file opening: Open JSP file [ ms ] / 1000 ms FC3 Sol9 Sol10 W2K WinXP 1st usage 2935 3128 3379 1734 1687 Subsequent usage 770 584 577 N/A N/A Closing as fixed for 5.0. Thanks to all who made the improvements! Verifying then ... Reopening because of increase of measured time values in Netbeans 5.5 builds. Open JSP file RHE Linux 3 Solaris 9 Win XP [ ms ] / 1000 ms 1st usage 3011 4125 1974 Subsequent usage 237 318 121 I think, that 300ms or 1000ms increase of 1st usage values should be fixed. For example i also present last values from Netbeans 5.0 builds,where also time values of 1st usage exceeded 4 seconds. Open JSP file RHE Linux 3 Solaris 9 Win XP [ ms ] / 1000 ms 1st usage 4704 4221 4020 Subsequent usage 241 303 144 Do we know what are the latest numbers for first opening of a Java file? Since the numbers for the 1st usage are way above the acceptable boundary for this kind of actions, and it does not look like we can get to the vicinity of 1000ms, should we think about adding a progress bar? Adding Jano to cc so he can comment. > ... should we think about adding a progress bar? ...
Progress bar makes real sense mainly for tasks that take more than 10 seconds.
Tasks between 1s and 10s should be usually indicated some other way (e.g.
hour-glass cursor)
And IMHO especially for opening a file the progress bar would look funny.
I believe we have UI responsiveness guidelines somewhere. I could only find this document: http://performance.netbeans.org/howto/wait-cursors.html Dusan, do we have a document that describes what kind of progress indication is appropriate for "Open File" use case? The first JSP page opening is terribly slow in 6.0 builds, there is plenty of new features now whose initialization takes a long time. The first JSP opening takes about 10-15 seconds on my machine. Needs to be addressed soon, increasing priority. I'll second this as confirmed. Also, for me its not just the first JSP. Pretty much any JSP I open takes about 15 seconds. Running latest nightly builds here with JDK 1.6_u1 on Kubuntu. Recent measurements: Open JSP file [ ms ] / 1000 ms Ubuntu, Solaris, WinXP 1st usage 4946 6664 2018 Subsequent usage 116 201 124 In recent build (20070912 according to attached chart) subsequent opening of jsp file became really slow, from 200-400ms to 5000+ ms Created attachment 48830 [details]
subsequent usage of jsp file
I tried to verify the subsequent JSP page opening regression but the subsequent file opening is almost instant to me. I tried bigger non-trivial JSPs but the same result. I guess that if you use the EDT events mechanism to measure the UI to stabilize there is some late paint which causes the test to measure invalid times. Can you please confirm that you can reproduce such long times during the subsequent jsp opening when measuring manually??? Actually, customers started to complain that in 20070912 opening is very slow and after that I've checked our measurements and updated the bug. In recent builds numbers for Subsequent usage are back to normal. Though 1st usage still exceeds boundary. I have build 20070927115727 and open JSP page take more than 10 seconds. mfukala, in profiler I noticed that JSPPaletteFactory.getPalette() is being called during first-time JSP opening. It takes on average about 250ms and because it is singleton I added this call to JspEditorWarmUpTask (I put it at the end of STATUS_RENDER_FRAME case). The figures I'm getting after this patch are quite interesting. I'm using Build 071002, WinXP, JDK 1.6.0_05-ea and I'm measuring time spent in BaseJspEditorSupport.open(). For testing I created regular Web Project with Struts support framework and I'm opening welcomeStruts.jsp. The numbers before my patch for first-time JSP opening are (in ms): 2359, 2156, 2125 The numbers when palette was created during startup are: 563, 766, 516 Before making any conclusions I would like to ask you (as expert in this area) whether you could try the same simple change and we will see what numbers you will come up with. Thx, David Great, feel free to commit if it helps, I do not have time to play with it now, sorry. BTW, how much time of the file opening (until the text is visible) is spent in the ES.open()? It seems to help but I before committing it I would like to test it on some other platform/pc. I will stop by on Monday - it will be quick. Committing proposed patch. Successfully tested on dkolar PC as well. Could perf tests be rerun please? Tentatively closing. If there is still perf problem the new issue should be opened. Thx David. Checking in core/src/org/netbeans/modules/web/core/JspEditorWarmUpTask.java; /cvs/web/core/src/org/netbeans/modules/web/core/JspEditorWarmUpTask.java new revision: 1.6; previous revision: 1.5 Open JSP file [ ms ] / 1000 ms 1st usage 1386 1538 1918 Subsequent usage 113 109 138 Within boundaries in last builds. Verified. |