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