If you have encountered performance issues my recommendation is to get YourKit
and take snapshots of CPU usage. If you capture just a few minutes of “normal”
activity I’d be happy to look at the snapshots and investigate whatever might
be going on. I should note that I do have a paid day job so these will need to
be related to Log4j 2 and you should not expect instant turnaround.
Ralph
> On Nov 19, 2020, at 7:59 PM, Laurent Hasson <l...@capsicohealth.com> wrote:
>
> 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>
>>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-user-h...@logging.apache.org
