This is a great thread. Thank you Lisa and the Log4J team for getting to the
bottom of this.
Moving to Java 11 has also been somewhat traumatic for us... this breakdown of
log4j performance at the feature level is fascinating to see. I hope some
article comes out of this once you all have figured it out.
Thank you,
Laurent.
Sent from my BlackBerry - the most secure mobile device
From: ralph.go...@dslextreme.com
Sent: November 19, 2020 21:07
To: lbru...@protonmail.com
Reply-to: log4j-user@logging.apache.org
Cc: volkan.yaz...@gmail.com; log4j-user@logging.apache.org
Subject: Re: log4j2 performance issues with Java 11
I am assuming you captured the snapshot from your profiling session? If so it
would be great it you could send it to me. I can email you privately with a
dropbox location where you can place the file if that will work for you.
FWIW, I find your results surprising as all %logger{36} should be doing is
truncating the logger name and including it. I would have expected formatting
the time or including the location info to be slower than dealing with the
logger.
Thanks,
Ralph
> On Nov 19, 2020, at 7:00 PM, Lisa Ruby <lbru...@protonmail.com> wrote:
>
> Hi,
>
> I have what I hope will be some useful information. I did what Volkan
> suggested and removed each log option mostly one at a time. I've pasted in
> the information I collected below. It appears that it's the %logger{36}
> option that is making the Console logging go so slow. Taking out other
> options speeds things up some, but taking out only %logger gets it to just
> about the same performance as on Java 8. Maybe that's only because less text
> is going to the Console? Don't know. Below this table is information from
> Profiling.
>
>
> Verified same things are being logged in both Java 8 and Java 11
>
>
>
> Java Version Test Description Time in seconds for Startup after Login
> Comments
> 8 Baseline test with nothing changed in app or log4j2.xml file 4
> 11 Baseline test with nothing changed in app or log4j2.xml file 25.7
> 11 Removed Rolling Log File logging from log4j2.xml. So Console only
> logging, no other changes to log4j2.xml 24.13
> 11 Removed only %L, Console only logging 23.78
> 11 Removed only [%t] Console only logging 16.79
> 11 Removed only %d{ISO8601}, Console only logging 18.11
> 11 Removed %d{ISO8601} and [%t], Console only logging 11.17
> 11 Removed only %logger{36}, Console only logging 5.89
>
>
> PROFILING
> -----------------
> I downloaded a trial version of the YourKit Java Profiler and have tried
> playing with it. I am running it as follows:
>
> I installed the Netbeans plugin
> Set the Options to Startup with CPU Profiling/Sampling.
> Ran Profile Main Project
> I then logged into my application and once it's fully started I checked the
> Method List and some other things
> I don't see java.util.Stackwalker listed in the Method List
> This is everything I see that is not my application class methods
>
> <pnbklipoafhdmcip.png>
>
> <olmafefjabpcodjc.png>
>
>
> Here is what it shows for the Log4j2 Thread in the Events by Table
>
> <ealilbphadpnkmce.png>
>
> The profiler is also warning me that there may be some deadlocks. It is
> beyond my knowledge level at this time to try to determine if there is
> actually a problem. I suspect not, but don't know for sure. This is what it
> tells me:
>
> <maephhbjpobfomco.png>
> <efheigahggegodgi.png>
>
>
> Let me know if there is any other information I can collect.
>
> Lisa
>
> On 11/19/2020 5:51 AM, Volkan Yazıcı wrote:
>> In the light of what Ralph mentioned about %L pattern, @Lisa, would you mind
>> seeing if simplifying the pattern (that is, removing certain directives bit
>> by bit, e.g., starting with %L) helps? Pinning down the actual smoking gun
>> would help us a lot.
>>
>> On Wed, Nov 18, 2020 at 4:50 PM Ralph Goers <ralph.go...@dslextreme.com
>> <mailto:ralph.go...@dslextreme.com>> wrote:
>> Is there any chance you could run your application under YourKit and profile
>> startup?
>>
>> Your partner uses %L so each log event needs to locate the location of the
>> caller. In Java 8 that used the com.sun.Reflection class but that was
>> removed in Java 9 so in Java 11 it would be using java.util.StackWalker. I
>> suspect the majority of the time will be there. I have made several attempts
>> to make that faster but haven’t seemed to find something that works for
>> everybody. So providing a profiling snapshot would help enormously.
>>
>> FWIW, Logging to the Console is known to be very slow, but I don’t believe
>> it should have changed that much between Java 8 and 11.
>>
>> Ralph
>>
>> > On Nov 17, 2020, at 11:11 PM, Lisa Ruby <lbru...@protonmail.com
>> > <mailto:lbru...@protonmail.com>.INVALID> wrote:
>> >
>> > I am working on moving my Java application development from Java 8 and
>> > JavaFX 8 to Java 11 and JavaFX 11, and am seeing a large performance
>> > degradation in log4j between Java 8 and Java 11.
>> >
>> > I've found these two issues that appear to have been addressed. Assuming
>> > whatever changes/fixes were involved got included in the latest
>> > releases, they have not fixed the issue I am seeing.
>> >
>> > https://github.com/line/armeria/issues/2306
>> > <https://github.com/line/armeria/issues/2306>
>> > https://issues.apache.org/jira/browse/LOG4J2-2537
>> > <https://issues.apache.org/jira/browse/LOG4J2-2537>
>> >
>> > For Java 11 I am using AdoptOpenJDK version 11.0.2, OpenJFX version
>> > 11.0.2, log4j version 2.14.0 (also tried 2.13.3, and 2.12.1), and
>> > NetBeans 12.0. In my Java 8 implementation I'm using log4j 2.12.1. I can
>> > supply JDK version if needed.
>> >
>> > Below is a general representation of what my log4j xml config file looks
>> > like. It's the same for Java 8 as for Java 11. I have a Loggers entry
>> > for each class in my application. They are all specified the same as the
>> > one shown here. In each class file I have code that looks like this:
>> >
>> > private static final Logger logger =
>> > LogManager.getLogger(ClassName.class.getName());
>> >
>> > XML File Sample
>> >
>> > <?xml version="1.0" encoding="UTF-8"?>
>> > <Configuration status="warn" monitorinterval="15">
>> > <Appenders>
>> > <Console name="Console" target="SYSTEM_OUT">
>> > <PatternLayout pattern="%d{ISO8601} [%t] %-5level %logger{36} -
>> > %L - %msg%n"/>
>> > </Console>
>> > <RollingFile name="RollingLogFile" fileName="logs/app.log"
>> > filePattern="logs/app-%i.log" >
>> > <PatternLayout>
>> > <pattern>%d{ISO8601}_%-5level_[%replace{%t}{stateofmyestate\.}{}]_%replace{%logger{36}}{stateofmyestate\.}{}_%L_%msg%n%ex</pattern>
>> > </PatternLayout>
>> > <Policies>
>> > <SizeBasedTriggeringPolicy size="5 MB" />
>> > </Policies>
>> > <DefaultRolloverStrategy max="5"/>
>> > </RollingFile>
>> > </Appenders>
>> > <Loggers>
>> > <Logger name = "appname.classname" level = "trace"
>> > additivity="false">
>> > <AppenderRef ref="RollingLogFile"/>
>> > <AppenderRef ref="Console"/>
>> > </Logger>
>> > <Root level="trace">
>> > <AppenderRef ref="Console"/>
>> > </Root>
>> > </Loggers>
>> > </Configuration>
>> >
>> > I have a lot of log messages, many of which are logged as the
>> > application is starting. When using Java 11 the logging is causing my
>> > application to take at least 6 times longer to start than with Java 8.
>> > With Java 8 it takes between 3 and 4 seconds. With Java 11 it takes 25
>> > seconds. I have some other functionality that also does a lot of logging
>> > when the log level is set to trace, and in that case the performance
>> > goes from seconds in Java 8 to several minutes in Java 11.
>> >
>> > I've tried various things to troubleshoot, and it appears to be
>> > something related to Console logging that is causing the performance
>> > issue. If I remove the Console Appenders from my configuration and leave
>> > only the RollingFile Appenders, the problem goes away. If I do the
>> > opposite and remove the RollingFile Appenders and leave the Console
>> > Appenders, I see a tiny improvement in the performance, but it's still
>> > way worse than in Java 8. So far I'm testing by running the application
>> > through NetBeans. I haven't tried starting the application from a
>> > Windows Command window yet. Running into some other issues doing that.
>> >
>> > Can anyone help me figure out if this is a log4j issue, or if there is
>> > something I can change in how I'm using log4j with Java 11, so I can
>> > resolve this issue?
>> >
>> > Thank you.
>> >
>> > Lisa Ruby
>> >
>> >
>> >
>> >
>> > ---------------------------------------------------------------------
>> > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
>> > <mailto:log4j-user-unsubscr...@logging.apache.org>
>> > For additional commands, e-mail: log4j-user-h...@logging.apache.org
>> > <mailto:log4j-user-h...@logging.apache.org>
>> >
>> >
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
>> <mailto:log4j-user-unsubscr...@logging.apache.org>
>> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>> <mailto:log4j-user-h...@logging.apache.org>
>>
>
