As I said, if you want to keep logging to the console you might consider
configuring the Loggers to be asynchronous. That way it shouldn’t affect the
speed of the application much, especially if you are primarily performing trace
and debug logging during initialization.
I might play around with the console appender myself and see if there are any
settings that can improve performance.
Ralph
> On Nov 22, 2020, at 12:12 AM, Lisa Ruby <lbru...@protonmail.com> wrote:
>
> Hi Ralph,
>
> Thank you for taking the time to investigate this, and for all of the
> information.
>
> You are correct, I forgot that I'd tested in Java 8 with the
> RollingFileAppender removed, and I obtained the YourKit profiler data
> without it. If you think it would be useful in any way I can also
> capture new profiler snapshots without the RollingFileAppender for Java 11.
>
> I created my patterns quite a long time ago and do not recall why I used
> {36} with the %logger option. I will look into that.
>
> I would prefer to keep logging to the Console during development.
> Obviously it's my choice if I want to deal with the performance hit to
> do that. It wasn't much of an issue in Java 8. For some classes I may
> need to turn it off so as not to slow down testing too much, or change
> the level I am logging unless I really need the trace.
>
> Lisa
>
>
> On 11/21/2020 12:33 AM, Ralph Goers wrote:
>> One other thing you could do to work around the problem I you really need to
>> log to the console is to configure your Loggers to be Async Loggers. If you
>> do that the I/O will still be slow but it shouldn’t impact the performance
>> of your application unless it is on a machine that only has a single core.
>>
>> Ralph
>>
>>> On Nov 21, 2020, at 1:30 AM, Ralph Goers <ralph.go...@dslextreme.com> wrote:
>>>
>>> Lisa, I am replying on list for others benefit but won’t include any
>>> details about your application.
>>>
>>> Lisa provided me with 3 snapshots: one running in Java 8, one running in
>>> Java 11 with %logger{36}, and one in Java 11 without it.
>>>
>>> First, the snapshots don’t show Log4j to be the main area of overhead but I
>>> am going to ignore that.
>>>
>>> I am noticing some differences between the snapshots
>>> In Java 8 the Log4j processing is about 420 ms. In Java 11 without
>>> %logger{36} it is about 875 ms and in Java 11 with %logger{36} the
>>> processing time is about 1,800 ms (1.8 seconds).
>>> A significant portion of that time is spent performing file I/O. In Java 11
>>> with %logger{36} it is spending 1,609 ms in java.io
>>> <http://java.io/>.FileOutputStream.writeBytes. I checked the source for
>>> that and it is a native method so it is unlikely anything in Log4j is
>>> called after that.
>>> I noticed the same pattern in the other 2 snapshots - the majority of the
>>> elapsed time is spent in the writeBytes method.
>>> In the Java 8 snapshot I don’t see any overhead in the RollingFileAppender.
>>> Was it disabled for that snapshot?
>>> Based on the call and time used patterns I can tell that
>>> AbstractOutputStreamAppender.directEncodeEvent is being called. For some
>>> reason that doesn’t take whether buffered I/O was requested into account
>>> and it seems it will flush on every call since immediateFlush defaults to
>>> true.
>>> I don’t seem any significant time being spent in any of the pattern
>>> converters, including the logger.
>>> While I believe I see both console logging and the rolling file appender in
>>> the Java 11 snapshots from what I can tell it is writing to the console
>>> that is causing the problem. This would agree with what you reported in
>>> your initial email.
>>>
>>> I suspect what is going on here is that every log event is resulting in a
>>> write. I suspect that when the logger name is included the line is simply
>>> becoming longer and makes the writes noticeably slower.
>>>
>>> As an aside I noticed you specified %logger{36}. That seems odd to me as it
>>> means you are expecting logger names with up to 36 dots in them. Were you
>>> really meaning to do something else?
>>>
>>> At this point I would try a couple of things:
>>> Replace %logger{36} with a string with a length that matches a typical
>>> logger name and see if that has the same result. If it does then that would
>>> support my hypothesis.
>>> Don’t log to the console. Our tests have shown that even in Java 8 it is up
>>> to 40 times slower than writing to a file.
>>>
>>> You could try writing a custom version of the ConsoleAppender that sets
>>> immediateFlush to false but I have never tested that and have no idea if it
>>> will help.
>>>
>>> None of this really explains why the calls to write the same message to the
>>> console in Java 11 is so much slower than in Java 8 but from what I am
>>> seeing the problem seems to be in java.io <http://java.io/> or something it
>>> is calling.
>>>
>>>
>>> Ralph
>>
>>
>> ---------------------------------------------------------------------
>> 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
