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: