Community
Participate
Working Groups
The compilation of (very simple) JSPs takes up to 10 seconds. This makes developing webapps quite cumbersome. This slow compilation can be observed on Windows 7 x64 and Ubuntu 32 Bit development machines when running virgo from eclipse (with spring dm tooling) and on CentOS 5.5 x64 on a standalong virgo instance. When I create a roo project on my development machine and deploy it in the embedded tc development server in eclipse (STS), the compilation of roo generated JSPs (which are far, far more complex) takes only fractions of a second. So I fear that "something" is slowing down the compilation of JSPs in Virgos tomcat instance.
Thanks for raising this. Please could you attach a minimal, binary example web app which demonstrates this behaviour plus set up instructions if there are any pre-req's other than Virgo. So we can determine if this is a regression, have you tried Virgo 2.1.0?
You may also like to bring this bug up in the Virgo forum as other users be interested or even have workarounds.
Assigning to Violeta who has expressed an interest in working on this. (Violeta: if you change your mind, please assign this bug back to virgo-inbox.)
I'll try to provide a small sample web bundle that shows this behaviour next week.
Thanks Jean-Pierre.
BTW: As proposed, I opened a thread in the forum: http://www.eclipse.org/forums/index.php?t=msg&th=208216
(In reply to comment #6) > BTW: As proposed, I opened a thread in the forum: > http://www.eclipse.org/forums/index.php?t=msg&th=208216 Hi, It will be very helpful if you provide a sample web bundle that I can use for further investigations. Also can you confirm that the issue appears also when using Virgo standalone i.e. not running Virgo from Eclipse. Thanks Regards Violeta
Our JSPs also compile slowly on a standalone virgo instance (running on CentOS). I tried to prepare a hello world web bundle, but this does not show this behaviour. I'll try to strip down our webapp so far that the behaviour can be shown and I'll post it here.
Created attachment 195059 [details] WAR that shows slow JSP compilation This war file shows the slow JSP compilation. When the webapp is freshly deployed or redeployed in Virgo, it takes very long until the first page appears (up to 10s on my machine). This happens when I run virgo standalone or from within eclipse. The compilation of the first JSP could be slower then the others, because the tiles have bo be compiled as well. But... When running a roo generated webapp (that also uses tiles and JSPs) in tc Development Server from within eclipse, also the first called JSP only takes a fraction of a second to compile and show up. The source code of this demo app can be found on: https://bitbucket.org/ractive/jsp-compilation Please tell me if you need more info. BTW: The context path of the app is "compile", so it should be reacheable on http://localhost:8080/compile The username in this demo app is "admin" and the password surprisingly also is "admin".
Any thoughts on this? I just made a "normal" war out of this project and deployed it on a tomcat 7, where it takes like 1.5 seconds to show up the first page. So it can be excluded that some misconfiguration in apache tiles or in Spring MVC cause this slow compilation. When running process monitor on windows, I see that the first compiled JSP file gets written after 17 seconds. Until then, just file reads take place and virgo eats up 100% of the CPU time of one core. Our main web project now already takes over 15s to show up the first JSP after deployment.
I used the "Process Monitor" tool on a Windows 7 64bit to see what the system is doing while compiling the JSPs on virgo and on a vanilla tomcat 7 installation. A summary of the file usage can be found on the following spreadsheet. There is a sheet for virgo and for tomcat 7. https://spreadsheets.google.com/spreadsheet/ccc?key=0AqrcoyW-9mpqdFhoNTA2LTV6WEM2akg4czdvM1BTcEE&hl=de&authkey=CMH3v5UC At first sight it seems as if files get opened far too many times in virgo. Some jars are read dozens of times! The tiles configuration default/layout.xml gets opened and closed 168 times (!!!), the javax.servlet.jsp jar gets opened and closed 279 times! As a comparison: on tomcat 7, the default/layout.xml file gets opened and closed 2 times, which is what to expect. I cannot find out what virgo is doing in between those many, many file accesses that causes the high CPU load.
I'm running the slow JSP compilation WAR in debugging bug 350404 and I observe that very little CPU is consumed. This is on Mac OS X. However, it still takes an age for some reason. Perhaps the slowness is all IO and this manifests itself as high CPU on Windows?
(In reply to comment #12) > I'm running the slow JSP compilation WAR in debugging bug 350404 and I observe > that very little CPU is consumed. This is on Mac OS X. However, it still takes > an age for some reason. > > Perhaps the slowness is all IO and this manifests itself as high CPU on > Windows? We could also observe a high CPU load on Ubuntu 32bit: One core is fully used by the virgo java process during the JSP compilation. High IO on Windows should not be reflected with high CPU load. When looking at the Process Monitor output, I can see that there is e.g. very little IO during t0 + 2s and 13s, but the CPU still is high.
Playing around with strace on an ubuntu 64bit also shows that there are many, many, many file accesses before/after/during (?) JSP compilation: jsp@v4-test:~/virgo$ sudo strace -p 7189 -f -e 'trace=!futex,gettimeofday,clock_gettime' -c Process 7189 attached with 95 threads - interrupt to quit % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 37.01 2.480000 72941 34 33 restart_syscall 30.44 2.040000 68000 30 recvfrom 15.22 1.020000 34000 30 poll 14.92 1.000000 500000 2 accept 2.39 0.160000 2424 66 fsync 0.01 0.000889 0 4001 lseek 0.00 0.000133 0 13921 6452 stat 0.00 0.000000 0 4269 read 0.00 0.000000 0 718 write 0.00 0.000000 0 179 open 0.00 0.000000 0 178 close 0.00 0.000000 0 98 fstat 0.00 0.000000 0 213 16 lstat 0.00 0.000000 0 82 mmap 0.00 0.000000 0 308 mprotect 0.00 0.000000 0 2 munmap 0.00 0.000000 0 60 rt_sigprocmask 0.00 0.000000 0 8 rt_sigreturn 0.00 0.000000 0 1 sched_yield 0.00 0.000000 0 22 madvise 0.00 0.000000 0 32 sendto 0.00 0.000000 0 4 setsockopt 0.00 0.000000 0 16 clone 0.00 0.000000 0 4 fcntl 0.00 0.000000 0 206 getdents 0.00 0.000000 0 5 rename 0.00 0.000000 0 14 5 mkdir 0.00 0.000000 0 5 unlink 0.00 0.000000 0 16 gettid 0.00 0.000000 0 32 sched_getaffinity 0.00 0.000000 0 16 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 6.701022 24572 6506 total
I profiled the first request (which compiles the JSP) and it involves a large amount of resource finding. Resource finding has shown up as a performance bottleneck in the past, compared to non-OSGi environments, especially when finding resources involves searching a bundle's dependencies. In this particular case, the web application depends on 41 other bundles. A particular hot spot is the use of Thread.currentThread().getStackTrace in MetaInfResourceClassLoaderDelegateHook. According to the class prologue, the hook propagates attempts to get META-INF resources to the principle bundle's dependencies, *unless* (and this involves getStackTrace) the request is being called from a DelegatedNamespaceHandlerResolver. A couple of simple optimisations in MetaInfResourceClassLoaderDelegateHook reduced the elapsed time for the request from about 37 seconds to about 9 seconds. See commit 79444d10c42ec7f26d72bf1cb11baf28dca9698b in the OSGi extensions git repository.
The fix will appear in 3.0.0.RC1 as it missed 3.0.0.M06.
Further optimisations may also be necessary, but the next one I would suggest is to reduce the number of direct dependencies of the web application. For instance, rather than using Import-Library and being wired to all Spring bundles, better to use bundlor or bnd to calculate the actual package dependencies.
This is really good news, thanks! 9s vs. 37s already is a good start with just "simple" optimizations. :-) Any ideas why the resource files of the web bundle itself are opened so many times?
I made a further simple optimisation, which will also appear in RC1. My latest measurements on a M05 base showed a latency of 24.7s for the servlet. With both optimisations in place, this reduced to 2.7s.
(In reply to comment #18) > Any ideas why the resource files of the web bundle itself are opened so many > times? I'm afraid not.
Further investigation of MetaInfResourceClassLoaderDelegateHook. According to this class's javadoc: * A {@link ClassLoaderDelegateHook} which in {@link #postFindResource} and {@link #postFindResources} propagates the * attempt to get <code>META-INF</code> resource(s) to the principle bundle's dependencies, unless the request is being * driven through Spring DM's DelgatedNamespaceHandlerResolver. It seems this class was introduced in September 2009 to cope with a scenario where an application depended on META-INF resources in its dependencies. There is no standard way in OSGi to express a dependency on such resources (although Equinox does allow bundles to export a META-INF "package" even though this doesn't conform to OSGi syntax, but then the dependent bundle needs to use Require-Bundle to obtain the dependency since META-INF may be split across multiple dependencies). MetaInfResourceClassLoaderDelegateHook avoids including META-INF resources from a bundle's immediate dependencies in any of the following cases: 1. Finding MANIFEST.MF 2. Finding spring/*.xml 3. Finding blueprint/*.xml although these resources are more likely to reside in OSGi_INF/blueprint 4. When the resource find is due to Spring DM or blueprint namespace handler resolution 5. When the resource find is due to delegated entity resolver processing 6. When the resource find is already delegated by MetaInfResourceClassLoaderDelegateHook. Cases 4 and 5 involve computing the current call stack and checking for the presence of specific class names. Apart from being fragile (e.g. if the specific class names change), the computation of the call stack can be costly. The first optimisation (comment 15), in OSGi extensions ([1]) commit 79444d10c42ec7f26d72bf1cb11baf28dca9698b, was to check for case 6 before computing the call stack for cases 4 and 5 as well as computing a single call stack rather than computing it once for case 4 and once for case 6. The second optimisation (comment 19), in OSGi extensions commit 824465e7f5eeb7b3fd4187b7e082475e1486bce1, was to use SecurityManager.getClassContext instead of Thread.currentThread().getStackTrace() to compute the call stack. I also tried removing the checks for cases 4 and 5 completely, but then the Spring DM extender failed to start, so this was clearly a bit drastic to slip in at this late stage of the 3.0 schedule! There is clearly some room for further improvement here, for example, by narrowing down which types of resources need this kind of find processing. Apparently JSP and TLD processing was working *before* we introduced this fix, so it must have been another, probably web, use case. Unfortunately, the specific use case is lost in the mists of time. [1] http://git.eclipse.org/c/virgo/org.eclipse.virgo.osgi-extensions.git/tree/
Note that WebAppClassLoaderDelegateHook (in the web integration layer of Virgo Tomcat Server) is used to delegate resource finds and class loads from a web application's bundle class loader to the corresponding web application class loader (created by Tomcat). So if it turns out that MetaInfResourceClassLoaderDelegateHook is really only needed for web resources, then it may be possible to move the logic out to WebAppClassLoaderDelegateHook to avoid the overhead for the Virgo Kernel and possibly the Virgo Jetty Server deliverables.
RC1 has been released and no one tells me... JSP compilation is much, much, much faster now and it seems as if the web app also gets started faster. Thanks for fixing this.
(In reply to comment #23) > RC1 has been released and no one tells me... RC2 is nearly out (just in case no-one tells you). This is a general problem with bugzilla (and JIRA for that matter) as there is no state transition of a bug when the fix gets released. > JSP compilation is much, much, much faster now and it seems as if the web app > also gets started faster. Thanks for fixing this. Great to hear the improvement appears to be sufficiently good.
Glyn, or anybody, can this be ported to virgo 2.1.0 ? If there are not resources to do it I understand. Any hints that would help me do it ? Thanks. Jan
Hi Jan (In reply to comment #25) > can this be ported to virgo 2.1.0 ? If there are not resources to do it I > understand. Any hints that would help me do it ? Should be straightforward to backport, but we don't have a suitable Virgo 2.1.x release planned, so you may wish to do this yourself. See comment 21 for the relevant commits. The OSGi extensions git repo is listed in the source tab of the Virgo wiki. Hope that helps! Regards, Glyn
