You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Lisa Ruby <lb...@protonmail.com.INVALID> on 2020/11/18 06:11:00 UTC
log4j2 performance issues with Java 11
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://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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
Than you for the input. I have added all of the apache jar files I need via Classpath, and have no need to modularize my application. Still having issues. My build is being created with ANT. Will try the profiling as soon as I can and get back to you.
Lisa
-------- Original Message --------
On Nov 18, 2020, 8:49 AM, Ralph Goers wrote:
> It should be. Normally you just have to add an agent to the command line for the application.
>
> If you are just placing everything on the classpath Java 11 should behave more or less like Java 8. However, if you are trying to use the module path and Java 11 modules you will likely have all kinds of interesting problems.
>
> Ralph
>
>> On Nov 18, 2020, at 9:00 AM, Lisa Ruby <lb...@protonmail.com.INVALID> wrote:
>>
>> Do you know if it's possible to run YourKit under NetBeans? I can try it
>> if I can do that. I'm having all kinds of other issues right now trying
>> to run my application outside of NetBeans. I'm using Apache FOP and
>> there are issues with the module architecture of Java 9+ and the jar
>> files needed by Apache FOP. Problems with module descriptors and
>> exceptions related to export of classes. Some of it is interactions with
>> classes used by log4j. Until I can figure out how to resolve these
>> problems I can only run under NetBeans. Not sure what NetBeans is doing
>> that allows it to run.
>>
>> Lisa
>>
>> On 11/18/2020 7:49 AM, Ralph Goers 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 <lb...@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://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-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>
>>>>
>>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
It should be. Normally you just have to add an agent to the command line for the application.
If you are just placing everything on the classpath Java 11 should behave more or less like Java 8. However, if you are trying to use the module path and Java 11 modules you will likely have all kinds of interesting problems.
Ralph
> On Nov 18, 2020, at 9:00 AM, Lisa Ruby <lb...@protonmail.com.INVALID> wrote:
>
> Do you know if it's possible to run YourKit under NetBeans? I can try it
> if I can do that. I'm having all kinds of other issues right now trying
> to run my application outside of NetBeans. I'm using Apache FOP and
> there are issues with the module architecture of Java 9+ and the jar
> files needed by Apache FOP. Problems with module descriptors and
> exceptions related to export of classes. Some of it is interactions with
> classes used by log4j. Until I can figure out how to resolve these
> problems I can only run under NetBeans. Not sure what NetBeans is doing
> that allows it to run.
>
> Lisa
>
> On 11/18/2020 7:49 AM, Ralph Goers 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 <lb...@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://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-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
Do you know if it's possible to run YourKit under NetBeans? I can try it
if I can do that. I'm having all kinds of other issues right now trying
to run my application outside of NetBeans. I'm using Apache FOP and
there are issues with the module architecture of Java 9+ and the jar
files needed by Apache FOP. Problems with module descriptors and
exceptions related to export of classes. Some of it is interactions with
classes used by log4j. Until I can figure out how to resolve these
problems I can only run under NetBeans. Not sure what NetBeans is doing
that allows it to run.
Lisa
On 11/18/2020 7:49 AM, Ralph Goers 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 <lb...@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://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-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
That could be. Having the snapshot with all the options enabled should be able to pinpoint what is using up the cpu time.
Ralph
> On Nov 19, 2020, at 8:39 PM, Lisa Ruby <lb...@protonmail.com> wrote:
>
> I did not grab the information from a Snapshot, just from the live capture on the screen. I will send you a private email regarding giving you an entire Snapshot.
>
> Regarding %logger{36}, I tested again, starting with my original xml config file and removing only the %logger{36} from the Console pattern. I left the RollingLogFile there this time and the application started in 6 seconds. So that definitely appears to be where the issue is. I do have a separate Logger for each of my classes. That wasn't a problem in Java 8, but maybe something about that is causing an issue in Java 11?
>
> Lisa
>
> On 11/19/2020 6:06 PM, Ralph Goers wrote:
>> 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 <lbruby1@protonmail.com <ma...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>>> > For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>> >
>>>> >
>>>>
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>>
>>>
>>
>
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
I did not grab the information from a Snapshot, just from the live capture on the screen. I will send you a private email regarding giving you an entire Snapshot.
Regarding %logger{36}, I tested again, starting with my original xml config file and removing only the %logger{36} from the Console pattern. I left the RollingLogFile there this time and the application started in 6 seconds. So that definitely appears to be where the issue is. I do have a separate Logger for each of my classes. That wasn't a problem in Java 8, but maybe something about that is causing an issue in Java 11?
Lisa
On 11/19/2020 6:06 PM, Ralph Goers wrote:
> 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 <lb...@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 <ra...@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 <lb...@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://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-unsubscribe@logging.apache.org
>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>>>
>>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
Thanks Ralph. I use logging throughout the application, as well as
during initialization. It has helped me many times to quickly debug
issues during development and testing. I can look into asynchronous
logging to see if it will work for me and help with the performance issue.
Lisa
On 11/21/2020 11:18 PM, Ralph Goers wrote:
> As I said, if you want to keep logging to the console you might consider configuring the Loggers to be asynchronous. That way it shouldn’t affect the speed of the application much, especially if you are primarily performing trace and debug logging during initialization.
>
> I might play around with the console appender myself and see if there are any settings that can improve performance.
>
> Ralph
>
>> On Nov 22, 2020, at 12:12 AM, Lisa Ruby <lb...@protonmail.com> wrote:
>>
>> Hi Ralph,
>>
>> Thank you for taking the time to investigate this, and for all of the
>> information.
>>
>> You are correct, I forgot that I'd tested in Java 8 with the
>> RollingFileAppender removed, and I obtained the YourKit profiler data
>> without it. If you think it would be useful in any way I can also
>> capture new profiler snapshots without the RollingFileAppender for Java 11.
>>
>> I created my patterns quite a long time ago and do not recall why I used
>> {36} with the %logger option. I will look into that.
>>
>> I would prefer to keep logging to the Console during development.
>> Obviously it's my choice if I want to deal with the performance hit to
>> do that. It wasn't much of an issue in Java 8. For some classes I may
>> need to turn it off so as not to slow down testing too much, or change
>> the level I am logging unless I really need the trace.
>>
>> Lisa
>>
>>
>> On 11/21/2020 12:33 AM, Ralph Goers wrote:
>>> One other thing you could do to work around the problem I you really need to log to the console is to configure your Loggers to be Async Loggers. If you do that the I/O will still be slow but it shouldn’t impact the performance of your application unless it is on a machine that only has a single core.
>>>
>>> Ralph
>>>
>>>> On Nov 21, 2020, at 1:30 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>>>>
>>>> Lisa, I am replying on list for others benefit but won’t include any details about your application.
>>>>
>>>> Lisa provided me with 3 snapshots: one running in Java 8, one running in Java 11 with %logger{36}, and one in Java 11 without it.
>>>>
>>>> First, the snapshots don’t show Log4j to be the main area of overhead but I am going to ignore that.
>>>>
>>>> I am noticing some differences between the snapshots
>>>> In Java 8 the Log4j processing is about 420 ms. In Java 11 without %logger{36} it is about 875 ms and in Java 11 with %logger{36} the processing time is about 1,800 ms (1.8 seconds).
>>>> A significant portion of that time is spent performing file I/O. In Java 11 with %logger{36} it is spending 1,609 ms in java.io <http://java.io/>.FileOutputStream.writeBytes. I checked the source for that and it is a native method so it is unlikely anything in Log4j is called after that.
>>>> I noticed the same pattern in the other 2 snapshots - the majority of the elapsed time is spent in the writeBytes method.
>>>> In the Java 8 snapshot I don’t see any overhead in the RollingFileAppender. Was it disabled for that snapshot?
>>>> Based on the call and time used patterns I can tell that AbstractOutputStreamAppender.directEncodeEvent is being called. For some reason that doesn’t take whether buffered I/O was requested into account and it seems it will flush on every call since immediateFlush defaults to true.
>>>> I don’t seem any significant time being spent in any of the pattern converters, including the logger.
>>>> While I believe I see both console logging and the rolling file appender in the Java 11 snapshots from what I can tell it is writing to the console that is causing the problem. This would agree with what you reported in your initial email.
>>>>
>>>> I suspect what is going on here is that every log event is resulting in a write. I suspect that when the logger name is included the line is simply becoming longer and makes the writes noticeably slower.
>>>>
>>>> As an aside I noticed you specified %logger{36}. That seems odd to me as it means you are expecting logger names with up to 36 dots in them. Were you really meaning to do something else?
>>>>
>>>> At this point I would try a couple of things:
>>>> Replace %logger{36} with a string with a length that matches a typical logger name and see if that has the same result. If it does then that would support my hypothesis.
>>>> Don’t log to the console. Our tests have shown that even in Java 8 it is up to 40 times slower than writing to a file.
>>>>
>>>> You could try writing a custom version of the ConsoleAppender that sets immediateFlush to false but I have never tested that and have no idea if it will help.
>>>>
>>>> None of this really explains why the calls to write the same message to the console in Java 11 is so much slower than in Java 8 but from what I am seeing the problem seems to be in java.io <http://java.io/> or something it is calling.
>>>>
>>>>
>>>> Ralph
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
As I said, if you want to keep logging to the console you might consider configuring the Loggers to be asynchronous. That way it shouldn’t affect the speed of the application much, especially if you are primarily performing trace and debug logging during initialization.
I might play around with the console appender myself and see if there are any settings that can improve performance.
Ralph
> On Nov 22, 2020, at 12:12 AM, Lisa Ruby <lb...@protonmail.com> wrote:
>
> Hi Ralph,
>
> Thank you for taking the time to investigate this, and for all of the
> information.
>
> You are correct, I forgot that I'd tested in Java 8 with the
> RollingFileAppender removed, and I obtained the YourKit profiler data
> without it. If you think it would be useful in any way I can also
> capture new profiler snapshots without the RollingFileAppender for Java 11.
>
> I created my patterns quite a long time ago and do not recall why I used
> {36} with the %logger option. I will look into that.
>
> I would prefer to keep logging to the Console during development.
> Obviously it's my choice if I want to deal with the performance hit to
> do that. It wasn't much of an issue in Java 8. For some classes I may
> need to turn it off so as not to slow down testing too much, or change
> the level I am logging unless I really need the trace.
>
> Lisa
>
>
> On 11/21/2020 12:33 AM, Ralph Goers wrote:
>> One other thing you could do to work around the problem I you really need to log to the console is to configure your Loggers to be Async Loggers. If you do that the I/O will still be slow but it shouldn’t impact the performance of your application unless it is on a machine that only has a single core.
>>
>> Ralph
>>
>>> On Nov 21, 2020, at 1:30 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>>>
>>> Lisa, I am replying on list for others benefit but won’t include any details about your application.
>>>
>>> Lisa provided me with 3 snapshots: one running in Java 8, one running in Java 11 with %logger{36}, and one in Java 11 without it.
>>>
>>> First, the snapshots don’t show Log4j to be the main area of overhead but I am going to ignore that.
>>>
>>> I am noticing some differences between the snapshots
>>> In Java 8 the Log4j processing is about 420 ms. In Java 11 without %logger{36} it is about 875 ms and in Java 11 with %logger{36} the processing time is about 1,800 ms (1.8 seconds).
>>> A significant portion of that time is spent performing file I/O. In Java 11 with %logger{36} it is spending 1,609 ms in java.io <http://java.io/>.FileOutputStream.writeBytes. I checked the source for that and it is a native method so it is unlikely anything in Log4j is called after that.
>>> I noticed the same pattern in the other 2 snapshots - the majority of the elapsed time is spent in the writeBytes method.
>>> In the Java 8 snapshot I don’t see any overhead in the RollingFileAppender. Was it disabled for that snapshot?
>>> Based on the call and time used patterns I can tell that AbstractOutputStreamAppender.directEncodeEvent is being called. For some reason that doesn’t take whether buffered I/O was requested into account and it seems it will flush on every call since immediateFlush defaults to true.
>>> I don’t seem any significant time being spent in any of the pattern converters, including the logger.
>>> While I believe I see both console logging and the rolling file appender in the Java 11 snapshots from what I can tell it is writing to the console that is causing the problem. This would agree with what you reported in your initial email.
>>>
>>> I suspect what is going on here is that every log event is resulting in a write. I suspect that when the logger name is included the line is simply becoming longer and makes the writes noticeably slower.
>>>
>>> As an aside I noticed you specified %logger{36}. That seems odd to me as it means you are expecting logger names with up to 36 dots in them. Were you really meaning to do something else?
>>>
>>> At this point I would try a couple of things:
>>> Replace %logger{36} with a string with a length that matches a typical logger name and see if that has the same result. If it does then that would support my hypothesis.
>>> Don’t log to the console. Our tests have shown that even in Java 8 it is up to 40 times slower than writing to a file.
>>>
>>> You could try writing a custom version of the ConsoleAppender that sets immediateFlush to false but I have never tested that and have no idea if it will help.
>>>
>>> None of this really explains why the calls to write the same message to the console in Java 11 is so much slower than in Java 8 but from what I am seeing the problem seems to be in java.io <http://java.io/> or something it is calling.
>>>
>>>
>>> Ralph
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
>
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
Hi Ralph,
Thank you for taking the time to investigate this, and for all of the
information.
You are correct, I forgot that I'd tested in Java 8 with the
RollingFileAppender removed, and I obtained the YourKit profiler data
without it. If you think it would be useful in any way I can also
capture new profiler snapshots without the RollingFileAppender for Java 11.
I created my patterns quite a long time ago and do not recall why I used
{36} with the %logger option. I will look into that.
I would prefer to keep logging to the Console during development.
Obviously it's my choice if I want to deal with the performance hit to
do that. It wasn't much of an issue in Java 8. For some classes I may
need to turn it off so as not to slow down testing too much, or change
the level I am logging unless I really need the trace.
Lisa
On 11/21/2020 12:33 AM, Ralph Goers wrote:
> One other thing you could do to work around the problem I you really need to log to the console is to configure your Loggers to be Async Loggers. If you do that the I/O will still be slow but it shouldn’t impact the performance of your application unless it is on a machine that only has a single core.
>
> Ralph
>
>> On Nov 21, 2020, at 1:30 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>>
>> Lisa, I am replying on list for others benefit but won’t include any details about your application.
>>
>> Lisa provided me with 3 snapshots: one running in Java 8, one running in Java 11 with %logger{36}, and one in Java 11 without it.
>>
>> First, the snapshots don’t show Log4j to be the main area of overhead but I am going to ignore that.
>>
>> I am noticing some differences between the snapshots
>> In Java 8 the Log4j processing is about 420 ms. In Java 11 without %logger{36} it is about 875 ms and in Java 11 with %logger{36} the processing time is about 1,800 ms (1.8 seconds).
>> A significant portion of that time is spent performing file I/O. In Java 11 with %logger{36} it is spending 1,609 ms in java.io <http://java.io/>.FileOutputStream.writeBytes. I checked the source for that and it is a native method so it is unlikely anything in Log4j is called after that.
>> I noticed the same pattern in the other 2 snapshots - the majority of the elapsed time is spent in the writeBytes method.
>> In the Java 8 snapshot I don’t see any overhead in the RollingFileAppender. Was it disabled for that snapshot?
>> Based on the call and time used patterns I can tell that AbstractOutputStreamAppender.directEncodeEvent is being called. For some reason that doesn’t take whether buffered I/O was requested into account and it seems it will flush on every call since immediateFlush defaults to true.
>> I don’t seem any significant time being spent in any of the pattern converters, including the logger.
>> While I believe I see both console logging and the rolling file appender in the Java 11 snapshots from what I can tell it is writing to the console that is causing the problem. This would agree with what you reported in your initial email.
>>
>> I suspect what is going on here is that every log event is resulting in a write. I suspect that when the logger name is included the line is simply becoming longer and makes the writes noticeably slower.
>>
>> As an aside I noticed you specified %logger{36}. That seems odd to me as it means you are expecting logger names with up to 36 dots in them. Were you really meaning to do something else?
>>
>> At this point I would try a couple of things:
>> Replace %logger{36} with a string with a length that matches a typical logger name and see if that has the same result. If it does then that would support my hypothesis.
>> Don’t log to the console. Our tests have shown that even in Java 8 it is up to 40 times slower than writing to a file.
>>
>> You could try writing a custom version of the ConsoleAppender that sets immediateFlush to false but I have never tested that and have no idea if it will help.
>>
>> None of this really explains why the calls to write the same message to the console in Java 11 is so much slower than in Java 8 but from what I am seeing the problem seems to be in java.io <http://java.io/> or something it is calling.
>>
>>
>> Ralph
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
Hi Ralph,
Thank you for taking the time to investigate this, and for all of the
information.
You are correct, I forgot that I'd tested in Java 8 with the
RollingFileAppender removed, and I obtained the YourKit profiler data
without it. If you think it would be useful in any way I can also
capture new profiler snapshots without the RollingFileAppender for Java 11.
I created my patterns quite a long time ago and do not recall why I used
{36} with the %logger option. I will look into that.
I would prefer to keep logging to the Console during development.
Obviously it's my choice if I want to deal with the performance hit to
do that. It wasn't much of an issue in Java 8. For some classes I may
need to turn it off so as not to slow down testing too much, or change
the level I am logging unless I really need the trace.
Lisa
On 11/21/2020 12:33 AM, Ralph Goers wrote:
> One other thing you could do to work around the problem I you really need to log to the console is to configure your Loggers to be Async Loggers. If you do that the I/O will still be slow but it shouldn’t impact the performance of your application unless it is on a machine that only has a single core.
>
> Ralph
>
>> On Nov 21, 2020, at 1:30 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>>
>> Lisa, I am replying on list for others benefit but won’t include any details about your application.
>>
>> Lisa provided me with 3 snapshots: one running in Java 8, one running in Java 11 with %logger{36}, and one in Java 11 without it.
>>
>> First, the snapshots don’t show Log4j to be the main area of overhead but I am going to ignore that.
>>
>> I am noticing some differences between the snapshots
>> In Java 8 the Log4j processing is about 420 ms. In Java 11 without %logger{36} it is about 875 ms and in Java 11 with %logger{36} the processing time is about 1,800 ms (1.8 seconds).
>> A significant portion of that time is spent performing file I/O. In Java 11 with %logger{36} it is spending 1,609 ms in java.io <http://java.io/>.FileOutputStream.writeBytes. I checked the source for that and it is a native method so it is unlikely anything in Log4j is called after that.
>> I noticed the same pattern in the other 2 snapshots - the majority of the elapsed time is spent in the writeBytes method.
>> In the Java 8 snapshot I don’t see any overhead in the RollingFileAppender. Was it disabled for that snapshot?
>> Based on the call and time used patterns I can tell that AbstractOutputStreamAppender.directEncodeEvent is being called. For some reason that doesn’t take whether buffered I/O was requested into account and it seems it will flush on every call since immediateFlush defaults to true.
>> I don’t seem any significant time being spent in any of the pattern converters, including the logger.
>> While I believe I see both console logging and the rolling file appender in the Java 11 snapshots from what I can tell it is writing to the console that is causing the problem. This would agree with what you reported in your initial email.
>>
>> I suspect what is going on here is that every log event is resulting in a write. I suspect that when the logger name is included the line is simply becoming longer and makes the writes noticeably slower.
>>
>> As an aside I noticed you specified %logger{36}. That seems odd to me as it means you are expecting logger names with up to 36 dots in them. Were you really meaning to do something else?
>>
>> At this point I would try a couple of things:
>> Replace %logger{36} with a string with a length that matches a typical logger name and see if that has the same result. If it does then that would support my hypothesis.
>> Don’t log to the console. Our tests have shown that even in Java 8 it is up to 40 times slower than writing to a file.
>>
>> You could try writing a custom version of the ConsoleAppender that sets immediateFlush to false but I have never tested that and have no idea if it will help.
>>
>> None of this really explains why the calls to write the same message to the console in Java 11 is so much slower than in Java 8 but from what I am seeing the problem seems to be in java.io <http://java.io/> or something it is calling.
>>
>>
>> Ralph
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
One other thing you could do to work around the problem I you really need to log to the console is to configure your Loggers to be Async Loggers. If you do that the I/O will still be slow but it shouldn’t impact the performance of your application unless it is on a machine that only has a single core.
Ralph
> On Nov 21, 2020, at 1:30 AM, Ralph Goers <ra...@dslextreme.com> wrote:
>
> Lisa, I am replying on list for others benefit but won’t include any details about your application.
>
> Lisa provided me with 3 snapshots: one running in Java 8, one running in Java 11 with %logger{36}, and one in Java 11 without it.
>
> First, the snapshots don’t show Log4j to be the main area of overhead but I am going to ignore that.
>
> I am noticing some differences between the snapshots
> In Java 8 the Log4j processing is about 420 ms. In Java 11 without %logger{36} it is about 875 ms and in Java 11 with %logger{36} the processing time is about 1,800 ms (1.8 seconds).
> A significant portion of that time is spent performing file I/O. In Java 11 with %logger{36} it is spending 1,609 ms in java.io <http://java.io/>.FileOutputStream.writeBytes. I checked the source for that and it is a native method so it is unlikely anything in Log4j is called after that.
> I noticed the same pattern in the other 2 snapshots - the majority of the elapsed time is spent in the writeBytes method.
> In the Java 8 snapshot I don’t see any overhead in the RollingFileAppender. Was it disabled for that snapshot?
> Based on the call and time used patterns I can tell that AbstractOutputStreamAppender.directEncodeEvent is being called. For some reason that doesn’t take whether buffered I/O was requested into account and it seems it will flush on every call since immediateFlush defaults to true.
> I don’t seem any significant time being spent in any of the pattern converters, including the logger.
> While I believe I see both console logging and the rolling file appender in the Java 11 snapshots from what I can tell it is writing to the console that is causing the problem. This would agree with what you reported in your initial email.
>
> I suspect what is going on here is that every log event is resulting in a write. I suspect that when the logger name is included the line is simply becoming longer and makes the writes noticeably slower.
>
> As an aside I noticed you specified %logger{36}. That seems odd to me as it means you are expecting logger names with up to 36 dots in them. Were you really meaning to do something else?
>
> At this point I would try a couple of things:
> Replace %logger{36} with a string with a length that matches a typical logger name and see if that has the same result. If it does then that would support my hypothesis.
> Don’t log to the console. Our tests have shown that even in Java 8 it is up to 40 times slower than writing to a file.
>
> You could try writing a custom version of the ConsoleAppender that sets immediateFlush to false but I have never tested that and have no idea if it will help.
>
> None of this really explains why the calls to write the same message to the console in Java 11 is so much slower than in Java 8 but from what I am seeing the problem seems to be in java.io <http://java.io/> or something it is calling.
>
>
> Ralph
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
Lisa, I am replying on list for others benefit but won’t include any details about your application.
Lisa provided me with 3 snapshots: one running in Java 8, one running in Java 11 with %logger{36}, and one in Java 11 without it.
First, the snapshots don’t show Log4j to be the main area of overhead but I am going to ignore that.
I am noticing some differences between the snapshots
In Java 8 the Log4j processing is about 420 ms. In Java 11 without %logger{36} it is about 875 ms and in Java 11 with %logger{36} the processing time is about 1,800 ms (1.8 seconds).
A significant portion of that time is spent performing file I/O. In Java 11 with %logger{36} it is spending 1,609 ms in java.io <http://java.io/>.FileOutputStream.writeBytes. I checked the source for that and it is a native method so it is unlikely anything in Log4j is called after that.
I noticed the same pattern in the other 2 snapshots - the majority of the elapsed time is spent in the writeBytes method.
In the Java 8 snapshot I don’t see any overhead in the RollingFileAppender. Was it disabled for that snapshot?
Based on the call and time used patterns I can tell that AbstractOutputStreamAppender.directEncodeEvent is being called. For some reason that doesn’t take whether buffered I/O was requested into account and it seems it will flush on every call since immediateFlush defaults to true.
I don’t seem any significant time being spent in any of the pattern converters, including the logger.
While I believe I see both console logging and the rolling file appender in the Java 11 snapshots from what I can tell it is writing to the console that is causing the problem. This would agree with what you reported in your initial email.
I suspect what is going on here is that every log event is resulting in a write. I suspect that when the logger name is included the line is simply becoming longer and makes the writes noticeably slower.
As an aside I noticed you specified %logger{36}. That seems odd to me as it means you are expecting logger names with up to 36 dots in them. Were you really meaning to do something else?
At this point I would try a couple of things:
Replace %logger{36} with a string with a length that matches a typical logger name and see if that has the same result. If it does then that would support my hypothesis.
Don’t log to the console. Our tests have shown that even in Java 8 it is up to 40 times slower than writing to a file.
You could try writing a custom version of the ConsoleAppender that sets immediateFlush to false but I have never tested that and have no idea if it will help.
None of this really explains why the calls to write the same message to the console in Java 11 is so much slower than in Java 8 but from what I am seeing the problem seems to be in java.io <http://java.io/> or something it is calling.
Ralph
Re: log4j2 performance issues with Java 11
Posted by Matt Sicker <bo...@gmail.com>.
Yes, the network lookup thing is a startup bug that only happens once
per JVM startup (or at least until its internal DNS caching expires
which by default doesn't expire until you restart the JVM).
On Fri, 20 Nov 2020 at 12:14, Lisa Ruby <lb...@protonmail.com> wrote:
>
> Hi Matt,
>
> Thank you for the input. I'm thinking this isn't relevant in my case.
> Does this only happen when the JVM first starts up?
>
> The areas where I am logging the most and where I see the big
> performance hit, are actually after the application and log4j have
> started. I called it startup, but it's more of an initialization of a
> lot of things after the application has been started, and I provide it
> with login credentials (it requires a login). There is another area
> where a lot of trace logging happens where I also see the performance
> issue with log4j.
>
> Lisa
>
> On 11/20/2020 7:38 AM, Matt Sicker wrote:
> > For startup time issues, there's also a Java "bug"/feature where if
> > you don't have an /etc/hosts entry for localhost, InetAddress does a
> > reverse name lookup on the loopback socket which ends up performing a
> > network request on some operating systems (macOS seems to attempt an
> > mDNS lookup of some sort to find the .local address). This is
> > mentioned on https://logging.apache.org/log4j/2.x/build.html and I
> > wonder if it's relevant at all here? Though that might not cause much
> > of a delay as it compounds a lot in unit tests.
> >
> > On Thu, 19 Nov 2020 at 21:45, Ralph Goers <ra...@dslextreme.com> wrote:
> >> Thanks. Actually I get as much out of this as user’s of Log4j will. For example, in this case if something in String processing is slower I want to know that so a) I can report it to the JDK team and b) so I can avoid these inefficiencies in my own code as well as the code my colleagues create.
> >>
> >> Ralph
> >>
> >>> On Nov 19, 2020, at 7:59 PM, Laurent Hasson <ld...@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.goers@dslextreme.com
> >>> Sent: November 19, 2020 21:07
> >>> To: lbruby1@protonmail.com
> >>> Reply-to: log4j-user@logging.apache.org
> >>> Cc: volkan.yazici@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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
> >>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
> >>>>>>
> >>>>>>
> >>>>>
> >>>>>
> >>>>> ---------------------------------------------------------------------
> >>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
> >>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
> >>>>>
> >>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> >> For additional commands, e-mail: log4j-user-help@logging.apache.org
> >>
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
Hi Matt,
Thank you for the input. I'm thinking this isn't relevant in my case.
Does this only happen when the JVM first starts up?
The areas where I am logging the most and where I see the big
performance hit, are actually after the application and log4j have
started. I called it startup, but it's more of an initialization of a
lot of things after the application has been started, and I provide it
with login credentials (it requires a login). There is another area
where a lot of trace logging happens where I also see the performance
issue with log4j.
Lisa
On 11/20/2020 7:38 AM, Matt Sicker wrote:
> For startup time issues, there's also a Java "bug"/feature where if
> you don't have an /etc/hosts entry for localhost, InetAddress does a
> reverse name lookup on the loopback socket which ends up performing a
> network request on some operating systems (macOS seems to attempt an
> mDNS lookup of some sort to find the .local address). This is
> mentioned on https://logging.apache.org/log4j/2.x/build.html and I
> wonder if it's relevant at all here? Though that might not cause much
> of a delay as it compounds a lot in unit tests.
>
> On Thu, 19 Nov 2020 at 21:45, Ralph Goers <ra...@dslextreme.com> wrote:
>> Thanks. Actually I get as much out of this as user’s of Log4j will. For example, in this case if something in String processing is slower I want to know that so a) I can report it to the JDK team and b) so I can avoid these inefficiencies in my own code as well as the code my colleagues create.
>>
>> Ralph
>>
>>> On Nov 19, 2020, at 7:59 PM, Laurent Hasson <ld...@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.goers@dslextreme.com
>>> Sent: November 19, 2020 21:07
>>> To: lbruby1@protonmail.com
>>> Reply-to: log4j-user@logging.apache.org
>>> Cc: volkan.yazici@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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Matt Sicker <bo...@gmail.com>.
For startup time issues, there's also a Java "bug"/feature where if
you don't have an /etc/hosts entry for localhost, InetAddress does a
reverse name lookup on the loopback socket which ends up performing a
network request on some operating systems (macOS seems to attempt an
mDNS lookup of some sort to find the .local address). This is
mentioned on https://logging.apache.org/log4j/2.x/build.html and I
wonder if it's relevant at all here? Though that might not cause much
of a delay as it compounds a lot in unit tests.
On Thu, 19 Nov 2020 at 21:45, Ralph Goers <ra...@dslextreme.com> wrote:
>
> Thanks. Actually I get as much out of this as user’s of Log4j will. For example, in this case if something in String processing is slower I want to know that so a) I can report it to the JDK team and b) so I can avoid these inefficiencies in my own code as well as the code my colleagues create.
>
> Ralph
>
> > On Nov 19, 2020, at 7:59 PM, Laurent Hasson <ld...@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.goers@dslextreme.com
> > Sent: November 19, 2020 21:07
> > To: lbruby1@protonmail.com
> > Reply-to: log4j-user@logging.apache.org
> > Cc: volkan.yazici@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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
> >>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
> >>>>
> >>>>
> >>>
> >>>
> >>>
> >>> ---------------------------------------------------------------------
> >>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
> >>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
> >>>
> >>
> >
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
Thanks. Actually I get as much out of this as user’s of Log4j will. For example, in this case if something in String processing is slower I want to know that so a) I can report it to the JDK team and b) so I can avoid these inefficiencies in my own code as well as the code my colleagues create.
Ralph
> On Nov 19, 2020, at 7:59 PM, Laurent Hasson <ld...@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.goers@dslextreme.com
> Sent: November 19, 2020 21:07
> To: lbruby1@protonmail.com
> Reply-to: log4j-user@logging.apache.org
> Cc: volkan.yazici@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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>>
>>>>
>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
RE: log4j2 performance issues with Java 11
Posted by Laurent Hasson <ld...@CapsicoHealth.com>.
We use basic features of Log4J and have not experienced measurable performance issues on our end. But other tools we use have gone through ups and downs such as Eclipse, Tomcat or Pentaho Kettle.
And in spite of your paid job, your help in this forum is constant. It's amazing and inspiring to see. Thanks to you and all the team.
Laurent Hasson
Co-Founder and CTO
CapsicoHealth Inc.
-----Original Message-----
From: Ralph Goers <ra...@dslextreme.com>
Sent: Thursday, November 19, 2020 22:11
To: Log4J Users List <lo...@logging.apache.org>
Subject: Re: log4j2 performance issues with Java 11
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 <ld...@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.goers@dslextreme.com
> Sent: November 19, 2020 21:07
> To: lbruby1@protonmail.com
> Reply-to: log4j-user@logging.apache.org
> Cc: volkan.yazici@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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org
>>>> <ma...@logging.apache.org>
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>> <ma...@logging.apache.org>
>>>>
>>>>
>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> - To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> <ma...@logging.apache.org>
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>> <ma...@logging.apache.org>
>>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
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 <ld...@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.goers@dslextreme.com
> Sent: November 19, 2020 21:07
> To: lbruby1@protonmail.com
> Reply-to: log4j-user@logging.apache.org
> Cc: volkan.yazici@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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>>
>>>>
>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>>
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Laurent Hasson <ld...@CapsicoHealth.com>.
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.goers@dslextreme.com
Sent: November 19, 2020 21:07
To: lbruby1@protonmail.com
Reply-to: log4j-user@logging.apache.org
Cc: volkan.yazici@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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>> > For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>> >
>> >
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>
>
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
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 <lb...@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.goers@dslextreme.com <ma...@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 <lbruby1@protonmail.com <ma...@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-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>> > For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>> >
>> >
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org <ma...@logging.apache.org>
>> For additional commands, e-mail: log4j-user-help@logging.apache.org <ma...@logging.apache.org>
>>
>
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
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
Here is what it shows for the Log4j2 Thread in the Events by Table
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:
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 <ra...@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 <lb...@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://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-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Lisa Ruby <lb...@protonmail.com.INVALID>.
Thank you for the suggestion. I will do that.
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 <ra...@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 <lb...@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://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-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>> For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: log4j2 performance issues with Java 11
Posted by Volkan Yazıcı <vo...@gmail.com>.
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 <ra...@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 <lb...@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://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-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
> >
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
Re: log4j2 performance issues with Java 11
Posted by Ralph Goers <ra...@dslextreme.com>.
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 <lb...@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://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-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org