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
