[
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16876289#comment-16876289
]
Ralph Goers edited comment on LOG4J2-2644 at 7/1/19 5:10 PM:
-------------------------------------------------------------
I made a version of calcLocation that behaves like jul by accessing the stack
through sun.misc.JavaLangAccess. This reduced the time to 38.072s from the
original time of 42.707s, which isn't much of an improvement considering it
requires using a class that may not be available in other Java implementations.
In looking at the jul profiling session vs the log4j profiling session the jul
version is simply spending much less time in java.lang.Throwable(int) then
Log4j. This makes sense since the Log4j stack depth is about 35 vs JULs which
is only 11. This leads to the obvious conclusion that if we could determine
that the location information is required earlier in the call stack we could
improve the performance considerably.
Oh - and for what it is worth I tried accessing sun.misc.JavaLangAccess through
reflection but that causes an IllegalAccessException. The class can only be
access via direct calls. Go figure.
I was able to validate my hypothesis by checking if isIncludeLocation specified
and causing the location to be calculated if it was true. This reduced the time
to:
||Java Version||Original Elapsed Time||New Elapsed Time||
|Java 8|42.707s|17.067s|
|Java 11|19.142s|10.136s|
Although these times are quite good I still need to do some sanity checking to
make sure this isn't enabling it when it shouldn't be as they are still
considerably slower than when the location is not enabled.
was (Author: [email protected]):
I made a version of calcLocation that behaves like jul by accessing the stack
through sun.misc.JavaLangAccess. This reduced the time to 38.072s from the
original time of 42.707s, which isn't much of an improvement considering it
requires using a class that may not be available in other Java implementations.
In looking at the jul profiling session vs the log4j profiling session the jul
version is simply spending much less time in java.lang.Throwable(int) then
Log4j. This makes sense since the Log4j stack depth is about 35 vs JULs which
is only 11. This leads to the obvious conclusion that if we could determine
that the location information is required earlier in the call stack we could
improve the performance considerably.
Oh - and for what it is worth I tried accessing sun.misc.JavaLangAccess through
reflection but that causes an IllegalAccessException. The class can only be
access via direct calls. Go figure.
> Logging with location information is considerably slower than logging with
> location information in java.util.logging
> --------------------------------------------------------------------------------------------------------------------
>
> Key: LOG4J2-2644
> URL: https://issues.apache.org/jira/browse/LOG4J2-2644
> Project: Log4j 2
> Issue Type: Improvement
> Affects Versions: 2.11.2
> Reporter: Marco Herrn
> Priority: Minor
> Time Spent: 2.5h
> Remaining Estimate: 0h
>
> according to https://logging.apache.org/log4j/2.x/performance.html logging
> with location information should be roughly the same performance for JUL
> and Log4j2.
> However I made a few comparisons between Log4j2 and JUL and in this case
> Log4j2 is much faster than JUL when omitting location information, but is
> considerably slower when logging with location information.
> Those are the results:
> JUL without location information : 32.162s
> JUL with location information : 21.682s
> Log4j2 without location information: 4.168s
> Log4j2 with location information : 59.000s
> In each case I logged 1500000 simple log statements (only a fixed string)
> and compared the timestamp of the first and the last generated log
> statement. Above you see the time spent between the first and the last log
> statement.
> I did these tests several times and the results are equal each time.
> In all cases I logged to a RollingFileAppender (or JULs equivalent).
> I assume that JUL with location information is faster than JUL without
> location information is because for JUL with location information I used a
> custom Formatter that doesn't support any configuration whereas I was
> using a SimpleFormatter with a specified formatstring for JUL without log
> information.
> It should be noted that I didn't use the Log4j2 API, but instead used the
> JUL logging API and used the log4j-jul-bridge to actually use Log4j2
> instead of the JUL implementation!
> I want to pay special attention to the difference when logging with
> location information, since I am puzzled that Log4j2 is that much slower
> than JUL in that case.
> The example code used for testing and the corresponding logging
> configurations can be found at [my example github
> project|http://github.com/hupfdule/LoggingPerformanceTest].
> I don't think there is anything special. Since when logging without
> location information Log4j2 is much faster than JUL there must be a
> difference between getting the location information. My above mentioned
> custom formatter uses the methods java.util.LogRecord#getSourceClassName()
> and java.util.LogRecord#getSourceMethodName() for obtaining that
> information. I haven't looked into how Log4j2 does it, but it seems to be
> much less efficient.
> I have done the tests with Java 8, but it seems that running it under Java 11
> shows the same behaviour.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
