glassfish
  1. glassfish
  2. GLASSFISH-18986

[PERF] Failed ClassLoading consuming too much logging time (~20% regression for ORB operations)

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 4.0_b48
    • Fix Version/s: 4.0_b82_EE7MS7
    • Component/s: orb
    • Labels:
      None

      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.

        Issue Links

          Activity

          Hide
          Harshad Vilekar added a comment -

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

          Show
          Harshad Vilekar added a comment - Issue under evaluation. Consider calling the logger only for the fine logging level.
          Hide
          Harshad Vilekar added a comment -

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

          Show
          Harshad Vilekar added a comment - Fixed in glassfish-corba 4.0.0-b005. hg changeset 862.
          Hide
          Scott Oaks added a comment -

          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.

          Show
          Scott Oaks added a comment - 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.
          Hide
          Harshad Vilekar added a comment -

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

          Show
          Harshad Vilekar added a comment - Similar fix is now applied to loadClassM() also. Fixed in glassfish-corba 4.0.0-b006. hg changeset 868.
          Hide
          Harshad Vilekar added a comment -

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

          Show
          Harshad Vilekar added a comment - Integrated glassfish-corba 4.0.0-b006. glassfish trunk svn revision 60838.

            People

            • Assignee:
              Harshad Vilekar
              Reporter:
              Scott Oaks
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: