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 <lbru...@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 <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
