[GLASSFISH-18986] [PERF] Failed ClassLoading consuming too much logging time (~20% regression for ORB operations) Created: 08/Aug/12  Updated: 20/Dec/16  Resolved: 26/Mar/13

Status: Resolved
Project: glassfish
Component/s: orb
Affects Version/s: 4.0_dev
Fix Version/s: 4.0_dev

Type: Bug Priority: Critical
Reporter: Scott Oaks Assignee: Harshad Vilekar
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Dependency
blocks GLASSFISH-18724 [PERF] Trade2 benchmark has regressed... Open
Tags: PSRBUG, Sev2_Candidate, vikkumar

 Description   

In Glassfish 4.0, one of the causes of the 40% regression we have in remote EJB performance comes from JDKBridge.loadClass – and in particular, when that calls the process classNotFoundInJDKClassLoader. That class in turn calls org.glassfish.pfl.basic.proxy.CompositeInvocationHandlerImpl.invoke -> org.glassfish.pfl.basic.logex.WrapperGenerator$2.invoke -> org.glassfish.pfl.basic.logex.WrapperGenerator.handleFullLogging -> org.glassfish.pfl.basic.logex.WrapperGenerator.trimStackTrace (which is enormously expensive because it walks the stack and interns dozens of strings along the way).

This all occurs when creating the stub while reading the cdr stream (CDRInputStream.read_Object -> StubFactoryFactoryDybamicBase.creaetStubFactory).

I guess that normal classloading semantics are in place here – it is looking first in the JDK classloader, and then will look in the app classloader. But while looking up the class in the JDK classloader will throw a ClassNotFoundException, we shouldn't be spending any time processing that exception for logging: the exception is never printed to the log (default logging settings are in place). So perhaps it is as simple along the way as making sure not to call into the logging code (including formatting the parameters for a call into the logger) unless the logging is really going to happen. Though in general, it would be better if the classloader could cache lookups like this so we don't have to repeatedly execute the same failed lookups.



 Comments   
Comment by Harshad Vilekar [ 11/Feb/13 ]

Issue under evaluation. Consider calling the logger only for the fine logging level.

Comment by Harshad Vilekar [ 14/Feb/13 ]

Fixed in glassfish-corba 4.0.0-b005. hg changeset 862.

Comment by Scott Oaks [ 18/Mar/13 ]

The loadClass() method now wraps the call to classNotFoundInJDKClassLoader with a fine logging statement, but the loadClassM() method is still calling it in all cases.

Comment by Harshad Vilekar [ 21/Mar/13 ]

Similar fix is now applied to loadClassM() also. Fixed in glassfish-corba 4.0.0-b006. hg changeset 868.

Comment by Harshad Vilekar [ 26/Mar/13 ]

Integrated glassfish-corba 4.0.0-b006. glassfish trunk svn revision 60838.

Generated at Mon Apr 24 05:01:29 UTC 2017 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.