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 <[email protected]> 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 <[email protected]
>> <mailto:[email protected]>> 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 <[email protected]
>> > <mailto:[email protected]>.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: [email protected]
>> > <mailto:[email protected]>
>> > For additional commands, e-mail: [email protected]
>> > <mailto:[email protected]>
>> >
>> >
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [email protected]
>> <mailto:[email protected]>
>> For additional commands, e-mail: [email protected]
>> <mailto:[email protected]>
>>
>
