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
