[
https://issues.apache.org/jira/browse/LOG4J2-2644?focusedWorklogId=269873&page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-269873
]
ASF GitHub Bot logged work on LOG4J2-2644:
------------------------------------------
Author: ASF GitHub Bot
Created on: 30/Jun/19 16:59
Start Date: 30/Jun/19 16:59
Worklog Time Spent: 10m
Work Description: carterkozak commented on pull request #289: LOG4J2-2644
- Improve performance of getting location info
URL: https://github.com/apache/logging-log4j2/pull/289#discussion_r298841873
##########
File path:
log4j-api-java9/src/main/java/org/apache/logging/log4j/util/StackLocator.java
##########
@@ -72,15 +78,40 @@ private StackLocator() {
}
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();
+ return walker.walk(s ->
s.filter(LOCATOR.get().setFqcn(fqcnOfLogger)).findFirst()).get().toStackTraceElement();
}
public StackTraceElement getStackTraceElement(final int depth) {
return stackWalker.walk(s ->
s.skip(depth).findFirst()).get().toStackTraceElement();
}
+
+ static final class CallerLocator implements
Predicate<StackWalker.StackFrame> {
+
+ private String fqcn;
+
+ private boolean foundFqcn = false;
+ private boolean foundLogger = false;
+
+ public CallerLocator setFqcn(String fqcn) {
+ this.fqcn = fqcn;
+ this.foundFqcn = false;
+ this.foundLogger = false;
+ return this;
+ }
+
+ @Override
+ public boolean test(StackWalker.StackFrame t) {
+ final String className = t.getClassName();
+ if (!foundLogger) {
+ if (!foundFqcn) {
+ foundFqcn = className.equals(fqcn);
+ return false;
+ } else if (!className.equals(fqcn)) {
+ foundLogger = true;
+ return true;
+ }
+ }
+ return false;
+ }
Review comment:
It took me a few reads through to understand how this works, would you mind
adding a comment to make it easier to understand?
Maybe something along these lines (if I understand correctly)
```java
/**
* States:
* 1. foundFqcn=false, foundLogger=false Nested in logging code, we must
first
* work our way up to frames from the loggers fully qualified class name.
* 2. foundFqcn=true, foundLogger=false Once we've found the logger, the next
* class we encounter which does not match the loggers fully qualified
class
* name is the caller.
* 3. foundFqcn=true, foundLogger=true Terminal state, if execution
continues after
* the logger is found, the caller is doing something incorrectly.
*/
public boolean test(StackWalker.StackFrame t) {
final String className = t.getClassName();
if (!foundLogger) {
if (!foundFqcn) {
foundFqcn = className.equals(fqcn);
return false;
} else if (!className.equals(fqcn)) {
foundLogger = true;
return true;
}
}
// Unexpected usage, CallerLocator.test has been invoked after the
logger has been found.
return false;
}
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
Issue Time Tracking
-------------------
Worklog Id: (was: 269873)
Time Spent: 50m (was: 40m)
> 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: 50m
> 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)
