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
