[jboss-jira] [JBoss JIRA] (LOGMGR-263) Logger Lookup is much slower as with JDK 8

[Emond Papegaaij (Jira)]

    [ https://issues.redhat.com/browse/LOGMGR-263?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13975980#comment-13975980 ] 

Emond Papegaaij commented on LOGMGR-263:
----------------------------------------

We are hitting this problem as well. In our application we see a lot of threads in {{getLogger}} (see attached stackdump). Many of these come from OpenSAML, where they use instance fields for loggers (or in some cases even create a new logger per log statement). See this link for more information on OpenSAML and the reason why they do logging like this: [SIDP-425|https://issues.shibboleth.net/jira/browse/SIDP-425?focusedCommentId=11699&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-11699] . The effect is that on a single SAML request, hundreds, if not thousands of loggers are instantiated.

To make things worse, the {{StackWalker}} seems to accumulate state on every call, making it slower over time. We see a steady increase in response times over time (see attached graph). This increase continues until a full GC runs, after which the response times return to normal. The entire delta (from less than 100ms to over 1s) is caused by logger lookups.

For now, we've developed a workaround for this issue by setting the {{LogContext}} at the beginning of the request and clearing it at the end (classes attached). This reduces the number of stack walks to one. This workaround also shows a severe weakness in the stack walking approach. When {{LogContextCacher}} is deployed in a war inside an ear, the call stack only contains stack frames in WildFly and Undertow and 1 frame in {{LogContextCacher}}. The {{LogContext}} that it should resolve is registered for the ear classloader. However, because none of the stack frames touch code in the ear classloader, it doesn't find this {{LogContext}} and returns the {{SYSTEM_CONTEXT}}. The parent classloader of a war deployment inside an ear is the {{jdk.internal.loader.ClassLoaders$AppClassLoader}}, not the ear classloader.

> Logger Lookup is much slower as with JDK 8
> ------------------------------------------
>
>                 Key: LOGMGR-263
>                 URL: https://issues.redhat.com/browse/LOGMGR-263
>             Project: JBoss Log Manager
>          Issue Type: Bug
>         Environment: WildFly 17, OpenJDK 11
>            Reporter: Andreas Liebscher
>            Priority: Major
>         Attachments: ClassInEar.java, LogContextCacher.java, getlogger-stack.txt, grafik1570016303722 (1).png, grafik1570016303722.png, grafik1570016791285.png, responsetimes.png
>
>
> During upgrading a Java EE application from WildFly 13 with JDK 8 to WildFly 17 with JDK 11 we had a serious performance issue. We identified the usage of the logging framework SLF4J with the pattern `Logger log = LoggerFactory.getLogger(XXX.class)` was the reason when a lot of calls to `getLogger` occur in parallel. As workaround we added `static` to some code hotspots to get back the performance we were used to. Also WildFly 13 with JDK 8 got a performance improvement with the added `static` keyword.
> Please check the VisualVM output as prove of JDKSpecific got slower:



--
This message was sent by Atlassian Jira
(v7.13.8#713008)