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
