[GLASSFISH-16560] very slow EAR deployment (annotation scanning seems to be very slow) Created: 05/May/11  Updated: 10/Oct/12

Status: Open
Project: glassfish
Component/s: deployment
Affects Version/s: 3.1
Fix Version/s: future release

Type: Improvement Priority: Major
Reporter: fmeili Assignee: Hong Zhang
Resolution: Unresolved Votes: 9
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Independent of OS and HW. Seen on Linux and Windows, 32 and 64 bit.

Attachments: Java Archive File dol.jar     File gf31_slow_ear_deployment.nps     File prof_with_dol_patch.nps    
Tags: 3_1_1-scrubbed, 3_1_1-scu, 3_1_x-exclude, annotation, deployment, ear, slow


Using the following EAR file:

18 jar files with 383 Stateless EJB's an 65 MDB in the root directory of the EAR archive.
19 war files with 66 Servlets in the root directory of the EAR archive.
152 jar files in the ./lib directory of the EAR file.
Size of EAR file is 75 MByte.

The EAR file deploys in GF 2.1.1 in 40 seconds. With GF 3.0, 3.1 (b43) and 3.2-SNAPSHOT it deploys in >400 seconds. So it deploys 10 times slower than in GF 2.1.1.

We use a lot of self developed annotations (>70) which reside in jar files in the ./lib directory of the EAR file.

The profiling shows us that the time gets consumed in the method com.sun.enterprise.deployment.annotation.impl.ModuleScanner.addScanURI(). This method is called from the method addLibraryJars() in the same class. It seems, that for all found annotation, the whole amount of jar files get always scanned for annotaions. This task takes very long time and is very cpu intensive. In my profile sample, the method addScanURI() is called many thousand times from the method addLibraryJars(). I think the result of already scanned classes for annotations should be remembered and reused.

I've attached a JVisualVM profiling file.

Comment by Hong Zhang [ 05/May/11 ]

Yeah, there is a difference in 2.1 and 3.1 for annotation processing. In 2.1, we did not do annotation processing for library jars which was a bug and we fixed it in 3.1.
However, when we process annotations in 3.1, we do only scan it once and store the results for late processing. The addScanURI API does not actually do the annotation scanning. The scanning was done only once in ApplicationLifecycle.getDeployableTypes and addScanURI is just matching the URI with the scanned results and get the relevant processed results.
While 152 jars is a big number of jars which is expected to take significant time in annotation scanning, 40s vs 400s does seem a big difference. We will take a look to see if there is anything else we can improve here. Maybe we can introduce a property when set to skip annotation processing for the library jars (as in this case, your library jars do not really need scanning/processing as they don't contain JavaEE annotations).

Comment by fmeili [ 05/May/11 ]

Are you sure that the GF 3.1 only scan each jar file once for annotation processing? What we see in the profiling data (see attached file), each jar file is scanned very often. We have 152 jar files in the ./lib directory, but the method addScanURI() is called 8208 times for one EAR deploy task.

In the attached nbs-file you'll see the profile for one EAR deploying. When you open the largest time consuming tree's you'll find that the Method com.sun.enterprise.deployment.annotation.impl.ModuleScanner.addScanURI() is called 5472 times from com.sun.enterprise.deployment.annotation.impl.ModuleScanner.process() and 2736 times from com.sun.enterprise.deployment.annotation.impl.WarScanner.process()). Both are the cpu hot spot points in the profile.

By the way, can you explain me in short why it's necessary to scan the whole ./lib directory for annotations, while deploying an ear?

Thanks for your fast answer,

Comment by Hong Zhang [ 05/May/11 ]

It's a Java EE platform spec requirement that all classes packaged inside the archive needs to be scanned for annotation. It's not recommended for the library jars to contain component annotations like @EJB etc, but it can include annotation like @ApplicationException.

I am a little surprised to hear that the addScanURI will be invoked so many times, I will look into the code to see what I can find.

Comment by fmeili [ 05/May/11 ]

If it would help you, I can provide you more cpu profiling data, stack traces or something else, please let me know.


Comment by Hong Zhang [ 05/May/11 ]

Looking at the code, I kind of understand why there will be so many addScanURI calls now.

For each module inside the ear, when we process annotations for that module, we will include the library jars as if the library jars were packaged directly in that module.

So for 152 library jars and 19 wars, you would get 152 x 19 = 2888 from the WarScanner.
And for 18 ejb jars, you would get 152 x 18 = 2736 from the EjbJarScanner.
And then as both classes call its super class ModuleScanner, the ModuleScanner.addScanURI should get called total 5624.

The numbers don't exactly match with your numbers yet, but I guess we know why there could be so many calls.

I still need to figure out why this addScanURI call is expensive, but certainly any method with this many number of calls will take a significant of time.

When we wrote the code, we did not think too much about this type of scenario with so many library jars and module jars. We will think about how to optimize for this type of scenario. Maybe as you said, we can try to cache the results of the library jar matching.

Comment by Hong Zhang [ 05/May/11 ]

I think I understand why the addScanURI is expensive now. It still have references to some old code where we used to scan the class again.

I have seen significant time improvement with a test case I created after I changed this part. I will do more testing and then check in the change to 3.1.1. As the 3.1 has FCSed, any bug fixes can only be made into 3.1.1 or 3.2. I can send you a patch for you to install locally and try too.

You can download 3.1.1 from here http://dlc.sun.com.edgesuite.net/glassfish/3.1.1/
once I check in my change.

Comment by fmeili [ 06/May/11 ]

Ok, good to hear that you've found the problem. I think, it will be helpful for you when I also test the patch locally on my system with our EAR file. Can I download the patch somewhere? Til now, the newest version, at the link you provided in your last message, is glassfish-3.1.1-b04.zip (form 4th May). Will the patch fit to this version?

Comment by Hong Zhang [ 06/May/11 ]

After you install the 3.1.1 build, replace the dol jar in the glassfish3/glassfish/modules directory with this patch dol.jar. Then try to deploy your application to see how much difference it makes.

Comment by Hong Zhang [ 06/May/11 ]

I just attached the patch in the issue. I think it should match with that 3.1.1 build, but if you see any problem, I can provide a patch for the 3.2 too (I plan to backport the change there too). You could do a baseline measurement before you install the patch. And then reinstall the build, and install the patch and see what difference it makes.

Comment by fmeili [ 09/May/11 ]

I've done some tests with the patch you've provided. The deployment time with the dol patch was shrinking from 400 seconds to 170 seconds, which is a big improvement.

Glassfish 3.1.1 b04 original: 400 s
Glassfish 3.1.1 with dol patch: 170 s
Glassfish 2.1.1 b31g-fcs: 40 s

Now the EAR deployment is not longer 10 times slower compared with GF 2.1.1, but is still 4 times slower. I've done some profiling with the dol patch, but sadly I couldn't find an additional single CPU hot spot (like in the version without the dol patch). As far as I can see, the most CPU time get consumed in annotation processing, but not at in a single method. There are a bunch of methods involved. I've attached a profiler snapshot with dol patch active. Maybe you can find something else which may be problematic while deploying.

Thank for your fast response and patch.
Greetings, Frank

Comment by Hong Zhang [ 09/May/11 ]

Frank thanks for verifying the patch! Glad this patch had made big improvement (and thanks again for reporting this and providing the profiling data pointing us to where we could improve significantly). I have checked in the changes into both 3.1.1 branch and the trunk (3.2) now.

For the next step, I will probably take a look to see if we can save the processed results for the libraries and re-use it for each module instead of doing this for each module. But please keep in mind, as we are now additionally processing these library jars while we didn't in 2.1, there will be always time differences compared to 2.1 (especially when the application contains large amount of library jars).

Comment by Hong Zhang [ 18/Oct/11 ]

Could not find any more simple set of the changes which could improve significantly. I am keeping this as a RFE for improvement in future release.

Comment by Hong Zhang [ 10/Oct/12 ]

Scrubbing RFEs for GlassFish 4.0.

Generated at Thu Nov 26 22:31:46 UTC 2015 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.