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