That could be. Having the snapshot with all the options enabled should be able
to pinpoint what is using up the cpu time.
Ralph
> On Nov 19, 2020, at 8:39 PM, Lisa Ruby <lbru...@protonmail.com> wrote:
>
> 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
>>> <mailto: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>
>>>>
>>>
>>
>
