Log4j 2
  1. Log4j 2
  2. LOG4J2-393

Low initialization performance when using Log4J with jar packages

    Details

      Description

      We discovered a huge performance difference when initializing Log4J with deployed jar packages compared to using it directly with normal class files.

      As it seems,
      org.apache.logging.log4j.core.config.plugins.ResolverUtil#loadImplementationsInJar
      is way slower than its counterpart
      org.apache.logging.log4j.core.config.plugins.ResolverUtil#loadImplementationsInDirectory
      and since this method gets called a few hundred times at initialization in this project, initialization of Log4J took more than 2 minutes with jar packages, compared to a few seconds with class files.

      The performance issue was already mentioned in LOG4J2-184, only without the jar problem.
      The solution to LOG4J2-175 might cause this, but we are unsure why the methods exactly get called this often.

      I just can tell that
      org.apache.logging.log4j.core.config.plugins.PluginManager#collectPlugins() gets called VERY often via
      org.apache.logging.log4j.core.config.BaseConfiguration#getPluginManager, which gets called by
      org.apache.logging.log4j.core.config.XMLConfiguration#constructHierarchy

      And collectPlugins() is remapped to collectPlugins(boolean preLoad, final String pkgs) with collectPlugins(true, null);. I'm unsure what this preLoad is for, since it gets overridden with false and apparently no kind of caching is used. In this method, resolver.findInPackage(test, pkg); takes a whole lot of time searching within the jars, as described in the beginning.

      The only way to work around this was for us to extract the custom appender in a sperate ant build target, and with this in a seperate jar, to minimize the size of the jar, reducing the search time.

      Can you cache things and maybe reduce the calls to collectPlugins()? I don't see the probability of changing plugins during initialization as described in LOG4J2-175 or the comment in org.apache.logging.log4j.core.config.BaseConfiguration#getPluginManager.
      Introducing a variable for the plugin manager within the for loop in org.apache.logging.log4j.core.config.XMLConfiguration#constructHierarchy might be a good idea!

        Activity

        Hide
        Philipp Hedwig added a comment -

        Ok, I tested it with rev. 1522449.

        I didn't get a logged warning, since obviously the logger isn't initialized at the moment when LOGGER.warn() gets called, but everything worked and loading times were much faster.
        ResolverUtil.findInPackage() still gets called too many times and is responsible for a great deal of the needed cpu time in intialization, but since this originates from PatternParser.PatternParser() I guess this can't be improved.

        Thanks a lot for your help and your quick responses.

        Show
        Philipp Hedwig added a comment - Ok, I tested it with rev. 1522449. I didn't get a logged warning, since obviously the logger isn't initialized at the moment when LOGGER.warn() gets called, but everything worked and loading times were much faster. ResolverUtil.findInPackage() still gets called too many times and is responsible for a great deal of the needed cpu time in intialization, but since this originates from PatternParser.PatternParser() I guess this can't be improved. Thanks a lot for your help and your quick responses.
        Hide
        Ralph Goers added a comment -

        Please verify and close.

        Show
        Ralph Goers added a comment - Please verify and close.
        Hide
        Ralph Goers added a comment - - edited

        I added code to catch the AbstractMethodError in revision 1521904. It will still log a warning but it should allow everything else to work. FWIW - the AbstractMethodError really is associated with LOG4J2-341, not this issue.

        Show
        Ralph Goers added a comment - - edited I added code to catch the AbstractMethodError in revision 1521904. It will still log a warning but it should allow everything else to work. FWIW - the AbstractMethodError really is associated with LOG4J2-341 , not this issue.
        Hide
        Philipp Hedwig added a comment -

        We are using Oracle JRE/JDK 1.7.0u09 on Win32. There are no libs in the endorsed path and we haven't intentionally overridden any classes of xerces or the JRE. We have a pretty old xerces.jar in our classpath, though.

        After removing our old xerces.jar from the classpath, further debugging showed, that the xalan.jar we are using defines a service META-INF/services/javax.xml.parsers.DocumentBuilderFactory linked to the org.apache.xerces.jaxp.DocumentBuilderFactoryImpl implementation of DocumentBuilderFactoryImpl. After removing the xerces.jar, the implementation can't be found. If we remove the service definition from the xalan.jar, then the fallback implementation from the JRE is used. But I don't know if this leads to problems with xalan itself ...

        Changing/removing this many libs can cause many problems and finding those by testing our application would be problematic, too. It's a high risk of crashes in the production environment.

        Updating xalan to the newest version or removing the jar helps with the DocumentBuilderFactory-problem, but I can't estimate the consequences. So a fallback option for extremely old xerces-versions would be very appreciated.

        Show
        Philipp Hedwig added a comment - We are using Oracle JRE/JDK 1.7.0u09 on Win32. There are no libs in the endorsed path and we haven't intentionally overridden any classes of xerces or the JRE. We have a pretty old xerces.jar in our classpath, though. After removing our old xerces.jar from the classpath, further debugging showed, that the xalan.jar we are using defines a service META-INF/services/javax.xml.parsers.DocumentBuilderFactory linked to the org.apache.xerces.jaxp.DocumentBuilderFactoryImpl implementation of DocumentBuilderFactoryImpl . After removing the xerces.jar, the implementation can't be found. If we remove the service definition from the xalan.jar, then the fallback implementation from the JRE is used. But I don't know if this leads to problems with xalan itself ... Changing/removing this many libs can cause many problems and finding those by testing our application would be problematic, too. It's a high risk of crashes in the production environment. Updating xalan to the newest version or removing the jar helps with the DocumentBuilderFactory -problem, but I can't estimate the consequences. So a fallback option for extremely old xerces-versions would be very appreciated.
        Hide
        Ralph Goers added a comment -

        I'm willing to bet that he has a copy of Xerces that doesn't support XIncludes in lib/endorsed. I'll add some code to handle this since.

        Show
        Ralph Goers added a comment - I'm willing to bet that he has a copy of Xerces that doesn't support XIncludes in lib/endorsed. I'll add some code to handle this since.
        Hide
        Gary Gregory added a comment -

        That is weird, the method is part of the public Java 6 API: http://docs.oracle.com/javase/6/docs/api/javax/xml/parsers/DocumentBuilderFactory.html#setFeature%28java.lang.String,%20boolean%29

        It's also in Java 5 FWIW so it has been around for a long time: http://docs.oracle.com/javase/1.5.0/docs/api/javax/xml/parsers/DocumentBuilderFactory.html#setFeature%28java.lang.String,%20boolean%29

        What is your Java set up like? Which version and vendor? Do have anything on the endorsed path? Did you override Xerces or any stock JRE classes?

        Show
        Gary Gregory added a comment - That is weird, the method is part of the public Java 6 API: http://docs.oracle.com/javase/6/docs/api/javax/xml/parsers/DocumentBuilderFactory.html#setFeature%28java.lang.String,%20boolean%29 It's also in Java 5 FWIW so it has been around for a long time: http://docs.oracle.com/javase/1.5.0/docs/api/javax/xml/parsers/DocumentBuilderFactory.html#setFeature%28java.lang.String,%20boolean%29 What is your Java set up like? Which version and vendor? Do have anything on the endorsed path? Did you override Xerces or any stock JRE classes?
        Hide
        Philipp Hedwig added a comment -

        I tried to test this with rev. 1521753, built new jar files and linked those in the project. Despite the on code level great looking changes, I get the following exception and stack trace during initialization:

        java.lang.AbstractMethodError: javax.xml.parsers.DocumentBuilderFactory.setFeature(Ljava/lang/String;Z)V
        	at org.apache.logging.log4j.core.config.XMLConfiguration.enableXInclude(XMLConfiguration.java:118)
        	at org.apache.logging.log4j.core.config.XMLConfiguration.newDocumentBuilder(XMLConfiguration.java:97)
        	at org.apache.logging.log4j.core.config.XMLConfiguration.<init>(XMLConfiguration.java:141)
        	at org.apache.logging.log4j.core.config.XMLConfigurationFactory.getConfiguration(XMLConfigurationFactory.java:40)
        	at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:375)
        	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:377)
        	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:149)
        	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:85)
        	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:34)
        	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:387)

        I checked beta8 and the difference is: Calls to factory.setNamespaceAware(true); and enableXInclude(factory); are new. (org.apache.logging.log4j.core.config.XMLConfiguration, lines 96 and 97)
        Somehow the provided DocumentBuilderFactory (org.apache.xerces.jaxp.DocumentBuilderFactoryImpl) seems to not have implemented the setFeature(String name, boolean value)-Method.

        This might prevent many from upgrading to the newest version, since it might be difficult to update the used xerces version.

        Show
        Philipp Hedwig added a comment - I tried to test this with rev. 1521753, built new jar files and linked those in the project. Despite the on code level great looking changes, I get the following exception and stack trace during initialization: java.lang.AbstractMethodError: javax.xml.parsers.DocumentBuilderFactory.setFeature(Ljava/lang/ String ;Z)V at org.apache.logging.log4j.core.config.XMLConfiguration.enableXInclude(XMLConfiguration.java:118) at org.apache.logging.log4j.core.config.XMLConfiguration.newDocumentBuilder(XMLConfiguration.java:97) at org.apache.logging.log4j.core.config.XMLConfiguration.<init>(XMLConfiguration.java:141) at org.apache.logging.log4j.core.config.XMLConfigurationFactory.getConfiguration(XMLConfigurationFactory.java:40) at org.apache.logging.log4j.core.config.ConfigurationFactory$Factory.getConfiguration(ConfigurationFactory.java:375) at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:377) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:149) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:85) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:34) at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:387) I checked beta8 and the difference is: Calls to factory.setNamespaceAware(true); and enableXInclude(factory); are new. ( org.apache.logging.log4j.core.config.XMLConfiguration , lines 96 and 97) Somehow the provided DocumentBuilderFactory ( org.apache.xerces.jaxp.DocumentBuilderFactoryImpl ) seems to not have implemented the setFeature(String name, boolean value) -Method. This might prevent many from upgrading to the newest version, since it might be difficult to update the used xerces version.
        Hide
        Ralph Goers added a comment -

        The changes described above were applied in revision 1521753. No changes to unit tests were needed. Please verify and close.

        Show
        Ralph Goers added a comment - The changes described above were applied in revision 1521753. No changes to unit tests were needed. Please verify and close.
        Hide
        Scott Deboy added a comment -

        Sounds good - I recall we had a conversation on the fact that there should be a single advertiser for the entire configuration. As long as this fits that model, it works for me. I assume the advertiser test will be updated as well when you're done?

        Show
        Scott Deboy added a comment - Sounds good - I recall we had a conversation on the fact that there should be a single advertiser for the entire configuration. As long as this fits that model, it works for me. I assume the advertiser test will be updated as well when you're done?
        Hide
        Ralph Goers added a comment - - edited

        Scott,

        I am noticing that the "advertiser" attribute is on the configuration element along with the "packages" attribute. Prior to the advertiser change the PluginManager was initialized in the start method in BaseConfiguration. In that case all the packages would already have been registered. When you moved the PluginManager initialization into XMLConfiguration you made it indeterminate since the packages element might be processed before or after the advertisers element.

        The "correct" way to do this is to create an advertisers Node in XMLConfiguration and JSONConfiguration and then perform that actual Plugin work in doConfiguration.

        I'm not sure what you mean by "lookups" as the config file isn't referencing any variables? Do you mean looking up plugins in the test package? That is done all over the place to get the ListAppender, AlwaysFailAppender, etc and worked just fine before the advertiser change.

        I am going to change the code to what I described above to correct this.

        Show
        Ralph Goers added a comment - - edited Scott, I am noticing that the "advertiser" attribute is on the configuration element along with the "packages" attribute. Prior to the advertiser change the PluginManager was initialized in the start method in BaseConfiguration. In that case all the packages would already have been registered. When you moved the PluginManager initialization into XMLConfiguration you made it indeterminate since the packages element might be processed before or after the advertisers element. The "correct" way to do this is to create an advertisers Node in XMLConfiguration and JSONConfiguration and then perform that actual Plugin work in doConfiguration. I'm not sure what you mean by "lookups" as the config file isn't referencing any variables? Do you mean looking up plugins in the test package? That is done all over the place to get the ListAppender, AlwaysFailAppender, etc and worked just fine before the advertiser change. I am going to change the code to what I described above to correct this.
        Hide
        Scott Deboy added a comment -

        This isn't advertiser-specific. I don't believe we had tests exercising lookups from additional config-defined packages, otherwise they would have failed as well.

        Show
        Scott Deboy added a comment - This isn't advertiser-specific. I don't believe we had tests exercising lookups from additional config-defined packages, otherwise they would have failed as well.
        Show
        Scott Deboy added a comment - Test: https://svn.apache.org/repos/asf/logging/log4j/log4j2/trunk/log4j-core/src/test/java/org/apache/logging/log4j/core/config/AdvertiserTest.java Associated xml config file: https://svn.apache.org/repos/asf/logging/log4j/log4j2/trunk/log4j-core/src/test/resources/log4j-advertiser.xml
        Hide
        Ralph Goers added a comment -

        Can you identify the test that had the problem? I'd like to review it to see what we can do.

        Show
        Ralph Goers added a comment - Can you identify the test that had the problem? I'd like to review it to see what we can do.
        Hide
        Scott Deboy added a comment -

        I believe this behavior changed when I needed to add the ability to add a test for the advertiser mechanism, which added a new package, and the new advertiser wasn't discovered until this logic was changed.

        Show
        Scott Deboy added a comment - I believe this behavior changed when I needed to add the ability to add a test for the advertiser mechanism, which added a new package, and the new advertiser wasn't discovered until this logic was changed.
        Hide
        Ralph Goers added a comment -

        I was actually looking at that recently. Originally, getPluginManager returned a cached object. Somewhere along the lines that was changed to allow new packages to be added. I think it needs to be made a little smarter to only create a new PluginManager if the packages have actually changed.

        Using a variable in constructHierarchy also seems like a very good idea.

        Show
        Ralph Goers added a comment - I was actually looking at that recently. Originally, getPluginManager returned a cached object. Somewhere along the lines that was changed to allow new packages to be added. I think it needs to be made a little smarter to only create a new PluginManager if the packages have actually changed. Using a variable in constructHierarchy also seems like a very good idea.

          People

          • Assignee:
            Unassigned
            Reporter:
            Philipp Hedwig
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development