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