You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Ralph Goers (JIRA)" <ji...@apache.org> on 2019/07/01 04:00:00 UTC
[jira] [Comment Edited] (LOG4J2-2644) Logging with location
information is considerably slower than logging with location information
in java.util.logging
[ https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16875576#comment-16875576 ]
Ralph Goers edited comment on LOG4J2-2644 at 7/1/19 3:59 AM:
-------------------------------------------------------------
I've cloned your project and had to modify it slightly. I had to copy the LPT class to Log4jPT and modify it to use Log4j directly as YourKit was encountering a deadlock in JMX stuff when trying to initialize. I get findings similar to yours:
With Java 8
||Test||Elapsed Time||
|jul_no_location|25.338s|
|jul_with_method|19.315s|
|log4j2_no_location|6.450s|
|log4j2_with_method|42.707s |
With Java 11
||Test||Elapsed Time||
|jul_no_location|25.905s|
|jul_with_method|23.003s|
|log4j2_no_location|7.441s|
|log4j2_with_method|30.763s|
From these it is obvious that StackWalker performs much better than walking a Throwable, at least for Log4j 2.
In looking at YourKit with Java 11 I am seeing:
Log4j2 - Total elapsed: 34.6221
||Method||Elapsed||Percentage||
|StackWalker.walk|21.891|64%|
|OutputStream.flush|7.411|21%|
JUL - Total elapsed: 21.707
||Method||Elapsed||Percentage||
|StackWalker.walk|9.296|42.8|
|OutputStreamWriter.flush|8.335|38.3|
The main difference between JUL and Log4j is that to locate the caller Log4j uses
{code:java}
public StackTraceElement calcLocation(final String fqcnOfLogger) {
return stackWalker.walk(
s -> s.dropWhile(f -> !f.getClassName().equals(fqcnOfLogger)) // drop the top frames until we reach the logger
.dropWhile(f -> f.getClassName().equals(fqcnOfLogger)) // drop the logger frames
.findFirst())
.get()
.toStackTraceElement();
}{code}
while JUL uses
{code:java}
static final class CallerFinder implements Predicate<StackWalker.StackFrame> {
private static final StackWalker WALKER;
static {
final PrivilegedAction<StackWalker> action =
() -> StackWalker.getInstance(StackWalker.Option.RETAIN_CLASS_REFERENCE);
WALKER = AccessController.doPrivileged(action);
}
/**
* Returns StackFrame of the caller's frame.
* @return StackFrame of the caller's frame.
*/
Optional<StackWalker.StackFrame> get() {
return WALKER.walk((s) -> s.filter(this).findFirst());
}
private boolean lookingForLogger = true;
/**
* Returns true if we have found the caller's frame, false if the frame
* must be skipped.
*
* @param t The frame info.
* @return true if we have found the caller's frame, false if the frame
* must be skipped.
*/
@Override
public boolean test(StackWalker.StackFrame t) {
final String cname = t.getClassName();
// We should skip all frames until we have found the logger,
// because these frames could be frames introduced by e.g. custom
// sub classes of Handler.
if (lookingForLogger) {
// the log record could be created for a platform logger
lookingForLogger = !isLoggerImplFrame(cname);
return false;
}
// Continue walking until we've found the relevant calling frame.
// Skips logging/logger infrastructure.
return !isFilteredFrame(t);
}
private boolean isLoggerImplFrame(String cname) {
return (cname.equals("java.util.logging.Logger") ||
cname.startsWith("sun.util.logging.PlatformLogger"));
}
}{code}
So the main differences are that JUL uses filter while Log4j uses dropWhile and JUL is only skipping the Logger classes while Log4j assumes it could be wrapped by custom Loggers and skips everything until it finds the passed FQCN. In general that means Log4j 2 is going have more frames to walk but it may also be that using filter instead of dropWhile is faster. I will have to test that.
I then also tested with Log4 2j 3.0.0-SNAPSHOT using the new builder pattern of logger.atInfo().withLocation().log(msg). After fixing a bug the results I saw dramatically better results:
||Java Version||Elapsed Time||
|java 8|9.823s|
|java 11|10.321s|
The Java 11 version uses
{code:java}
public StackTraceElement getStackTraceElement(final int depth) {
return stackWalker.walk(s -> s.skip(depth).findFirst()).get().toStackTraceElement();
}{code}
with a depth value of 2. Unfortunately, it isn't really possible to add this form of StackWalker to the original API methods since they can be wrapped and so the depth can't accurately be determined.
was (Author: ralph.goers@dslextreme.com):
I've cloned your project and had to modify it slightly. I had to copy the LPT class to Log4jPT and modify it to use Log4j directly as YourKit was encountering a deadlock in JMX stuff when trying to initialize. I get findings similar to yours:
With Java 8
||Test||Elapsed Time||
|jul_no_location|25.338s|
|jul_with_method|19.315s|
|log4j2_no_location|6.450s|
|log4j2_with_method|42.707s |
With Java 11
||Test||Elapsed Time||
|jul_no_location|25.905s|
|jul_with_method|23.003s|
|log4j2_no_location|7.441s|
|log4j2_with_method|30.763s|
From these it is obvious that StackWalker performs much better than sun.reflect.Reflection, at least for Log4j 2.
In looking at YourKit with Java 11 I am seeing:
Log4j2 - Total elapsed: 34.6221
||Method||Elapsed||Percentage||
|StackWalker.walk|21.891|64%|
|OutputStream.flush|7.411|21%|
JUL - Total elapsed: 21.707
||Method||Elapsed||Percentage||
|StackWalker.walk|9.296|42.8|
|OutputStreamWriter.flush|8.335|38.3|
The main difference between JUL and Log4j is that to locate the caller Log4j uses
{code:java}
public StackTraceElement calcLocation(final String fqcnOfLogger) {
return stackWalker.walk(
s -> s.dropWhile(f -> !f.getClassName().equals(fqcnOfLogger)) // drop the top frames until we reach the logger
.dropWhile(f -> f.getClassName().equals(fqcnOfLogger)) // drop the logger frames
.findFirst())
.get()
.toStackTraceElement();
}{code}
while JUL uses
{code:java}
static final class CallerFinder implements Predicate<StackWalker.StackFrame> {
private static final StackWalker WALKER;
static {
final PrivilegedAction<StackWalker> action =
() -> StackWalker.getInstance(StackWalker.Option.RETAIN_CLASS_REFERENCE);
WALKER = AccessController.doPrivileged(action);
}
/**
* Returns StackFrame of the caller's frame.
* @return StackFrame of the caller's frame.
*/
Optional<StackWalker.StackFrame> get() {
return WALKER.walk((s) -> s.filter(this).findFirst());
}
private boolean lookingForLogger = true;
/**
* Returns true if we have found the caller's frame, false if the frame
* must be skipped.
*
* @param t The frame info.
* @return true if we have found the caller's frame, false if the frame
* must be skipped.
*/
@Override
public boolean test(StackWalker.StackFrame t) {
final String cname = t.getClassName();
// We should skip all frames until we have found the logger,
// because these frames could be frames introduced by e.g. custom
// sub classes of Handler.
if (lookingForLogger) {
// the log record could be created for a platform logger
lookingForLogger = !isLoggerImplFrame(cname);
return false;
}
// Continue walking until we've found the relevant calling frame.
// Skips logging/logger infrastructure.
return !isFilteredFrame(t);
}
private boolean isLoggerImplFrame(String cname) {
return (cname.equals("java.util.logging.Logger") ||
cname.startsWith("sun.util.logging.PlatformLogger"));
}
}{code}
So the main differences are that JUL uses filter while Log4j uses dropWhile and JUL is only skipping the Logger classes while Log4j assumes it could be wrapped by custom Loggers and skips everything until it finds the passed FQCN. In general that means Log4j 2 is going have more frames to walk but it may also be that using filter instead of dropWhile is faster. I will have to test that.
I then also tested with Log4 2j 3.0.0-SNAPSHOT using the new builder pattern of logger.atInfo().withLocation().log(msg). After fixing a bug the results I saw dramatically better results:
||Java Version||Elapsed Time||
|java 8|9.823s|
|java 11|10.321s|
The Java 11 version uses
{code:java}
public StackTraceElement getStackTraceElement(final int depth) {
return stackWalker.walk(s -> s.skip(depth).findFirst()).get().toStackTraceElement();
}{code}
with a depth value of 2. Unfortunately, it isn't really possible to add this form of StackWalker to the original API methods since they can be wrapped and so the depth can't accurately be determined.
> 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: 1h 10m
> 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)