Thanks Ralph. I use logging throughout the application, as well as
during initialization. It has helped me many times to quickly debug
issues during development and testing. I can look into asynchronous
logging to see if it will work for me and help with the performance issue.
Lisa
On 11/21/2020 11:18 PM, Ralph Goers wrote:
> 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
