Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-27100

[GSS](7.4.z) Logger is slower with log4j filter on JDK11

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • 7.4.18.CR1, 7.4.18.GA
    • 7.4.16.GA
    • Logging
    • None
    • False
    • False
    • -
    • Undefined
    • Workaround Exists
    • Hide

      remove filter definition from log4j.xml/properties.

         <appender name="stdout" class="org.apache.log4j.ConsoleAppender">
            ...
            <filter class="org.apache.log4j.varia.StringMatchFilter">
               <param name="StringToMatch" value="test" />
               <param name="AcceptOnMatch" value="false" />
            </filter>
            ...
         </appender>
      

      or defining exclusion setting per application

      • include log4j jar file to WEB-INF/lib (if using commons-logging, that needs to be included also.)
      • WEB-INF/jboss-deployment-structure.xml
        <jboss-deployment-structure>
            <deployment>
              <exclusions>
                <module name="org.apache.log4j"/>
                <module name="org.apache.commons.logging"/>
              </exclusions>
            </deployment>
        </jboss-deployment-structure>
        
      • set use-deployment-logging-config=false to logging subsystem
      Show
      remove filter definition from log4j.xml/properties. <appender name= "stdout" class= "org.apache.log4j.ConsoleAppender" > ... <filter class= "org.apache.log4j.varia.StringMatchFilter" > <param name= "StringToMatch" value= "test" /> <param name= "AcceptOnMatch" value= " false " /> </filter> ... </appender> or defining exclusion setting per application include log4j jar file to WEB-INF/lib (if using commons-logging, that needs to be included also.) WEB-INF/jboss-deployment-structure.xml <jboss-deployment-structure> <deployment> <exclusions> <module name= "org.apache.log4j" /> <module name= "org.apache.commons.logging" /> </exclusions> </deployment> </jboss-deployment-structure> set use-deployment-logging-config=false to logging subsystem
    • Hide

      1. EAP start with JDK11
      2. deploy a reproducer
      $ unzip hello.zip
      $ cd hello
      $ mvn package wildfly:deploy
      3. send request
      $ curl -v http://localhost:8080/hello/test

      Show
      1. EAP start with JDK11 2. deploy a reproducer $ unzip hello.zip $ cd hello $ mvn package wildfly:deploy 3. send request $ curl -v http://localhost:8080/hello/test

      When defining log4j filters in log4j.xml or properties in webapp, getLogger() occurred at org.apache.log4j.JBossFilterWrapper.isLoggable() [1].
      Running with JDK11, the logger lookup is much slower than JDK 8 and high cpu loaded even though the version was fixed for JBEAP-19267.
      This slowness can be seen both 7.3.5 and 7.2.9.

      [1]

      "default task-1" #165 prio=5 os_prio=0 cpu=2405.82ms elapsed=2.66s tid=0x0000559632236800 nid=0x2f2e runnable  [0x00007fa84327a000]
         java.lang.Thread.State: RUNNABLE
      	at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.7/Native Method)
      	at java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames(java.base@11.0.7/StackStreamFactory.java:386)
      	at java.lang.StackStreamFactory$AbstractStackWalker.getNextBatch(java.base@11.0.7/StackStreamFactory.java:322)
      	at java.lang.StackStreamFactory$AbstractStackWalker.peekFrame(java.base@11.0.7/StackStreamFactory.java:263)
      	at java.lang.StackStreamFactory$AbstractStackWalker.hasNext(java.base@11.0.7/StackStreamFactory.java:351)
      	at java.lang.StackStreamFactory$StackFrameTraverser.tryAdvance(java.base@11.0.7/StackStreamFactory.java:593)
      	at java.util.Spliterators$1Adapter.hasNext(java.base@11.0.7/Spliterators.java:681)
      	at org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply(JDKSpecific.java:210)
      	at org.jboss.logmanager.JDKSpecific$FindAllWalkFunction.apply(JDKSpecific.java:198)
      	at java.lang.StackStreamFactory$StackFrameTraverser.consumeFrames(java.base@11.0.7/StackStreamFactory.java:534)
      	at java.lang.StackStreamFactory$AbstractStackWalker.doStackWalk(java.base@11.0.7/StackStreamFactory.java:306)
      	at java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk(java.base@11.0.7/Native Method)
      	at java.lang.StackStreamFactory$AbstractStackWalker.beginStackWalk(java.base@11.0.7/StackStreamFactory.java:370)
      	at java.lang.StackStreamFactory$AbstractStackWalker.walk(java.base@11.0.7/StackStreamFactory.java:243)
      	at java.lang.StackWalker.walk(java.base@11.0.7/StackWalker.java:498)
      	at org.jboss.logmanager.JDKSpecific.logContextFinder(JDKSpecific.java:70)
      	at org.jboss.logmanager.ClassLoaderLogContextSelector$2.run(ClassLoaderLogContextSelector.java:109)
      	at org.jboss.logmanager.ClassLoaderLogContextSelector$2.run(ClassLoaderLogContextSelector.java:107)
      	at org.jboss.logmanager.ClassLoaderLogContextSelector.getLogContext(ClassLoaderLogContextSelector.java:122)
      	at org.jboss.as.logging.logmanager.WildFlyLogContextSelectorImpl.getLogContext(WildFlyLogContextSelectorImpl.java:75)
      	at org.jboss.logmanager.LogContext.getLogContext(LogContext.java:301)
      	at org.apache.log4j.JBossLogManagerFacade$1.run(JBossLogManagerFacade.java:37)
      	at org.apache.log4j.JBossLogManagerFacade$1.run(JBossLogManagerFacade.java:34)
      	at org.apache.log4j.JBossLogManagerFacade.doPrivileged(JBossLogManagerFacade.java:269)
      	at org.apache.log4j.JBossLogManagerFacade.getLogContext(JBossLogManagerFacade.java:246)
      	at org.apache.log4j.JBossLogManagerFacade.getJBossLogger(JBossLogManagerFacade.java:52)
      	at org.apache.log4j.JBossLogManagerFacade.getOrCreateLogger(JBossLogManagerFacade.java:148)
      	at org.apache.log4j.Hierarchy.getLogger(Hierarchy.java:130)
      	at org.apache.log4j.Hierarchy.getLogger(Hierarchy.java:125)
      	at org.apache.log4j.LogManager.getLogger(LogManager.java:57)
      	at org.apache.log4j.Logger.getLogger(Logger.java:35)
      	at org.apache.log4j.JBossFilterWrapper.isLoggable(JBossFilterWrapper.java:27)
      	at org.apache.log4j.JBossAppenderHandler.doPublish(JBossAppenderHandler.java:33)
      	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:77)
      	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:333)
      	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
      	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
      	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
      	at org.jboss.logmanager.Logger.logRaw(Logger.java:852)
      	at org.apache.log4j.Category.callAppenders(Category.java:69)
      	at org.apache.log4j.Category.forcedLog(Category.java:121)
      	at org.apache.log4j.Category.debug(Category.java:82)
      	at com.example.TestServlet.doGet(TestServlet.java:23)
      

      For example, the reproducer attached calls Log.debug() 100,000 times in 1 request. Then the execution time of JDK11 is about 3 times slower on my test.

      • JDK8
        INFO stdout - Instantiating 100000 loggers: duration = 8340024975 nanos = 8340 millis = 8 seconds
      • JDK11
        INFO stdout - Instantiating 100000 loggers: duration = 24177532183 nanos = 24177 millis = 24 seconds

        1. hello.zip
          5 kB
        2. threaddump.zip
          22 kB

            rhn-support-ivassile Ilia Vassilev
            rhn-support-hdaicho Hiroki Daicho (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            8 Start watching this issue

              Created:
              Updated:
              Resolved: