[jira] [Work logged] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[ASF GitHub Bot (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2644?focusedWorklogId=269815=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#worklog-269815
 ]

ASF GitHub Bot logged work on LOG4J2-2644:
--

Author: ASF GitHub Bot
Created on: 30/Jun/19 03:49
Start Date: 30/Jun/19 03:49
Worklog Time Spent: 10m 
  Work Description: rgoers commented on pull request #289: LOG4J2-2644 - 
Improve performance of getting location info
URL: https://github.com/apache/logging-log4j2/pull/289
 
 
   Improves the performance of getting location info.
 

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:
us...@infra.apache.org


Issue Time Tracking
---

Worklog Id: (was: 269815)
Time Spent: 10m
Remaining Estimate: 0h

> 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: 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 150 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)

[GitHub] [logging-log4j2] rgoers opened a new pull request #289: LOG4J2-2644 - Improve performance of getting location info

[GitBox]

rgoers opened a new pull request #289: LOG4J2-2644 - Improve performance of 
getting location info
URL: https://github.com/apache/logging-log4j2/pull/289
 
 
   Improves the performance of getting location info.


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:
us...@infra.apache.org


With regards,
Apache Git Services

[GitHub] [logging-log4j2] rgoers opened a new pull request #288: Log4 j2 2644 for release-2.x

[GitBox]

rgoers opened a new pull request #288: Log4 j2 2644 for release-2.x
URL: https://github.com/apache/logging-log4j2/pull/288
 
 
   Improves performance of calculating location info.


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:
us...@infra.apache.org


With regards,
Apache Git Services

[jira] [Commented] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[ASF subversion and git services (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875642#comment-16875642
 ] 

ASF subversion and git services commented on LOG4J2-2644:
-

Commit 0c638e681e21b58883e178000db40bfdacb9db02 in logging-log4j2's branch 
refs/heads/LOG4J2-3644-3.x from Ralph Goers
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=0c638e6 ]

LOG4J2-2644 - Improve performance of getting location info


> 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
>
> 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 150 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)

[jira] [Commented] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[ASF subversion and git services (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875641#comment-16875641
 ] 

ASF subversion and git services commented on LOG4J2-2644:
-

Commit c880137015623c66988faa7c11bda6f22adc66f2 in logging-log4j2's branch 
refs/heads/LOG4J2-2644-2.x from Ralph Goers
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=c880137 ]

LOG4J2-2644 - Improve performance of getting location info


> 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
>
> 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 150 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)

[jira] [Comment Edited] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875636#comment-16875636
 ] 

Ralph Goers edited comment on LOG4J2-2644 at 6/30/19 3:41 AM:
--

I reimplemented calcLocation to use filter instead of dropWhile. The new 
results for Java 11 are now 20.653s which cuts the previous time by a third and 
makes it faster than the jul version. I will create PRs for this.

FWIW, I looked at the Oracle implementation for Java 7. It uses 
sun.misc.SharedSecrets to access the stack trace. That wouldn't necessarily 
work in other vendors so I'd be reluctant to use it.


was (Author: ralph.go...@dslextreme.com):
I reimplemented calcLocation to use filter instead of dropWhile. The new 
results for Java 11 are now 20.653s which cuts the previous time by a third and 
makes it faster than the jul version. I will create PRs for this.

> 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
>
> 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 150 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)

[jira] [Commented] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Remko Popma (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875640#comment-16875640
 ] 

Remko Popma commented on LOG4J2-2644:
-

Nice work, Ralph!

I’ve started to look into using byte code libraries to inject location at 
compile time, but this is still very early stages. 

> 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
>
> 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 150 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)

[jira] [Commented] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875636#comment-16875636
 ] 

Ralph Goers commented on LOG4J2-2644:
-

I reimplemented calcLocation to use filter instead of dropWhile. The new 
results for Java 11 are now 20.653s which cuts the previous time by a third and 
makes it faster than the jul version. I will create PRs for this.

> 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
>
> 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 150 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)

[jira] [Comment Edited] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875576#comment-16875576
 ] 

Ralph Goers edited comment on LOG4J2-2644 at 6/30/19 3:07 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 
>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 {
private static final StackWalker WALKER;
static {
final PrivilegedAction 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 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.go...@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||

[jira] [Comment Edited] (LOG4J2-2636) No default value for mdcId in SyslogAppender

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875613#comment-16875613
 ] 

Ralph Goers edited comment on LOG4J2-2636 at 6/29/19 11:00 PM:
---

I don't understand. If you don't provide a default value for the Layout it will 
get a default value provided by the Layout. If you don't provide a default 
value for the SyslogAppender it will get the default value provided by the 
Layout.  What is the problem with that? In both cases it will get the same 
default value.


was (Author: ralph.go...@dslextreme.com):
I don't understand. If you don't provided a default value for the Layout it 
will get a default value provided by the Layout. If you don't provide a default 
value for the SyslogAppender it will get the default value provided by the 
Layout.  What is the problem with that? In both cases it will get the same 
default value.

> No default value for mdcId in SyslogAppender
> 
>
> Key: LOG4J2-2636
> URL: https://issues.apache.org/jira/browse/LOG4J2-2636
> Project: Log4j 2
>  Issue Type: Bug
>Affects Versions: 2.11.2
>Reporter: Filipp Gunbin
>Priority: Major
> Fix For: 2.12.1
>
>
> 1) Main issue
> When Rfc5424Layout is created from configuration, it seems to receive default 
> value:
> {code:java}
> @PluginAttribute(value = "mdcId", defaultString = DEFAULT_MDCID) final String 
> mdcId,{code}
> But SyslogAppender has it with no default:
> {code:java}
> @PluginBuilderAttribute("mdcId")
> private String mdcId;{code}
> It is used in SyslogAppender.build() to create Rfc5424Layout.  So, if I don't 
> specify "mdcId" attribute in " config element, I get this exception:
> {quote}ERROR StatusLogger Could not create plugin of type class 
> org.apache.logging.log4j.core.appender.SyslogAppender for element Syslog: 
> java.lang.IllegalArgumentException: No structured id name was supplied 
> java.lang.IllegalArgumentException: No structured id name was supplied at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:146)
>  at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:130)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.(Rfc5424Layout.java:142)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.createLayout(Rfc5424Layout.java:672)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:117)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:50)
> {quote}
> 2) Documentation doesn't mention mdcId of SyslogAppender at all: 
> [https://logging.apache.org/log4j/2.x/manual/appenders.html#SyslogAppender]
> If I build site locally with "mvn site" in 2.11.2, it's not there either.
> 3) Commit ce1183629fe89625a77872c7153853e7774502a6 
> (https://issues.apache.org/jira/browse/LOG4J2-922) which introduces default 
> value for mdcId in Rfc5424Layout has this code:
> {code:java}
> this.mdcId = id == null ? DEFAULT_MDCID : id;         
> this.mdcSdId = new StructuredDataId(mdcId, enterpriseNumber, null, 
> null);{code}
> While "this.mdcId" is set in first line, the argument (not class member) 
> mdcId is used in the second line.  Maybe argument mdcId should be used in the 
> first line instead of "id"?  Maybe this.mdcId should be used in the second 
> line instead of argument mdcId? I'm not familiar with the code enough to tell 
> for sure, it just feels suspicious to me.
> Thanks.
>  



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Comment Edited] (LOG4J2-2636) No default value for mdcId in SyslogAppender

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875613#comment-16875613
 ] 

Ralph Goers edited comment on LOG4J2-2636 at 6/29/19 11:00 PM:
---

I don't understand. If you don't provide a value for the Layout it will get a 
default value provided by the Layout. If you don't provide a value for the 
SyslogAppender it will get the default value provided by the Layout.  What is 
the problem with that? In both cases it will get the same default value.


was (Author: ralph.go...@dslextreme.com):
I don't understand. If you don't provide a default value for the Layout it will 
get a default value provided by the Layout. If you don't provide a default 
value for the SyslogAppender it will get the default value provided by the 
Layout.  What is the problem with that? In both cases it will get the same 
default value.

> No default value for mdcId in SyslogAppender
> 
>
> Key: LOG4J2-2636
> URL: https://issues.apache.org/jira/browse/LOG4J2-2636
> Project: Log4j 2
>  Issue Type: Bug
>Affects Versions: 2.11.2
>Reporter: Filipp Gunbin
>Priority: Major
> Fix For: 2.12.1
>
>
> 1) Main issue
> When Rfc5424Layout is created from configuration, it seems to receive default 
> value:
> {code:java}
> @PluginAttribute(value = "mdcId", defaultString = DEFAULT_MDCID) final String 
> mdcId,{code}
> But SyslogAppender has it with no default:
> {code:java}
> @PluginBuilderAttribute("mdcId")
> private String mdcId;{code}
> It is used in SyslogAppender.build() to create Rfc5424Layout.  So, if I don't 
> specify "mdcId" attribute in " config element, I get this exception:
> {quote}ERROR StatusLogger Could not create plugin of type class 
> org.apache.logging.log4j.core.appender.SyslogAppender for element Syslog: 
> java.lang.IllegalArgumentException: No structured id name was supplied 
> java.lang.IllegalArgumentException: No structured id name was supplied at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:146)
>  at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:130)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.(Rfc5424Layout.java:142)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.createLayout(Rfc5424Layout.java:672)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:117)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:50)
> {quote}
> 2) Documentation doesn't mention mdcId of SyslogAppender at all: 
> [https://logging.apache.org/log4j/2.x/manual/appenders.html#SyslogAppender]
> If I build site locally with "mvn site" in 2.11.2, it's not there either.
> 3) Commit ce1183629fe89625a77872c7153853e7774502a6 
> (https://issues.apache.org/jira/browse/LOG4J2-922) which introduces default 
> value for mdcId in Rfc5424Layout has this code:
> {code:java}
> this.mdcId = id == null ? DEFAULT_MDCID : id;         
> this.mdcSdId = new StructuredDataId(mdcId, enterpriseNumber, null, 
> null);{code}
> While "this.mdcId" is set in first line, the argument (not class member) 
> mdcId is used in the second line.  Maybe argument mdcId should be used in the 
> first line instead of "id"?  Maybe this.mdcId should be used in the second 
> line instead of argument mdcId? I'm not familiar with the code enough to tell 
> for sure, it just feels suspicious to me.
> Thanks.
>  



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Commented] (LOG4J2-2636) No default value for mdcId in SyslogAppender

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875613#comment-16875613
 ] 

Ralph Goers commented on LOG4J2-2636:
-

I don't understand. If you don't provided a default value for the Layout it 
will get a default value provided by the Layout. If you don't provide a default 
value for the SyslogAppender it will get the default value provided by the 
Layout.  What is the problem with that? In both cases it will get the same 
default value.

> No default value for mdcId in SyslogAppender
> 
>
> Key: LOG4J2-2636
> URL: https://issues.apache.org/jira/browse/LOG4J2-2636
> Project: Log4j 2
>  Issue Type: Bug
>Affects Versions: 2.11.2
>Reporter: Filipp Gunbin
>Priority: Major
> Fix For: 2.12.1
>
>
> 1) Main issue
> When Rfc5424Layout is created from configuration, it seems to receive default 
> value:
> {code:java}
> @PluginAttribute(value = "mdcId", defaultString = DEFAULT_MDCID) final String 
> mdcId,{code}
> But SyslogAppender has it with no default:
> {code:java}
> @PluginBuilderAttribute("mdcId")
> private String mdcId;{code}
> It is used in SyslogAppender.build() to create Rfc5424Layout.  So, if I don't 
> specify "mdcId" attribute in " config element, I get this exception:
> {quote}ERROR StatusLogger Could not create plugin of type class 
> org.apache.logging.log4j.core.appender.SyslogAppender for element Syslog: 
> java.lang.IllegalArgumentException: No structured id name was supplied 
> java.lang.IllegalArgumentException: No structured id name was supplied at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:146)
>  at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:130)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.(Rfc5424Layout.java:142)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.createLayout(Rfc5424Layout.java:672)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:117)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:50)
> {quote}
> 2) Documentation doesn't mention mdcId of SyslogAppender at all: 
> [https://logging.apache.org/log4j/2.x/manual/appenders.html#SyslogAppender]
> If I build site locally with "mvn site" in 2.11.2, it's not there either.
> 3) Commit ce1183629fe89625a77872c7153853e7774502a6 
> (https://issues.apache.org/jira/browse/LOG4J2-922) which introduces default 
> value for mdcId in Rfc5424Layout has this code:
> {code:java}
> this.mdcId = id == null ? DEFAULT_MDCID : id;         
> this.mdcSdId = new StructuredDataId(mdcId, enterpriseNumber, null, 
> null);{code}
> While "this.mdcId" is set in first line, the argument (not class member) 
> mdcId is used in the second line.  Maybe argument mdcId should be used in the 
> first line instead of "id"?  Maybe this.mdcId should be used in the second 
> line instead of argument mdcId? I'm not familiar with the code enough to tell 
> for sure, it just feels suspicious to me.
> Thanks.
>  



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

Build failed in Jenkins: Log4j 2 3.x #443

[Apache Jenkins Server]

See 


Changes:

[gardgregory] [LOG4J2-2646] Update MongoDB 3 driver from 3.10.1 to 3.10.2.

--
[...truncated 101.09 KB...]
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/commons/commons-lang3/3.9/commons-lang3-3.9.pom
 (28 KB at 1630.2 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/commons/commons-parent/48/commons-parent-48.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/commons/commons-parent/48/commons-parent-48.pom
 (71 KB at 3908.1 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-plugin-api/3.6.0/maven-plugin-api-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-plugin-api/3.6.0/maven-plugin-api-3.6.0.pom
 (3 KB at 191.7 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/org.eclipse.sisu.plexus/0.3.3/org.eclipse.sisu.plexus-0.3.3.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/org.eclipse.sisu.plexus/0.3.3/org.eclipse.sisu.plexus-0.3.3.pom
 (5 KB at 271.5 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/sisu-plexus/0.3.3/sisu-plexus-0.3.3.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/sisu-plexus/0.3.3/sisu-plexus-0.3.3.pom
 (14 KB at 893.6 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/org.eclipse.sisu.inject/0.3.3/org.eclipse.sisu.inject-0.3.3.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/org.eclipse.sisu.inject/0.3.3/org.eclipse.sisu.inject-0.3.3.pom
 (3 KB at 183.1 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/sisu-inject/0.3.3/sisu-inject-0.3.3.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/eclipse/sisu/sisu-inject/0.3.3/sisu-inject-0.3.3.pom
 (15 KB at 938.0 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-model-builder/3.6.0/maven-model-builder-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-model-builder/3.6.0/maven-model-builder-3.6.0.pom
 (3 KB at 184.8 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-resolver-provider/3.6.0/maven-resolver-provider-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-resolver-provider/3.6.0/maven-resolver-provider-3.6.0.pom
 (5 KB at 256.6 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-api/1.3.1/maven-resolver-api-1.3.1.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-api/1.3.1/maven-resolver-api-1.3.1.pom
 (3 KB at 155.5 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver/1.3.1/maven-resolver-1.3.1.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver/1.3.1/maven-resolver-1.3.1.pom
 (17 KB at 817.2 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-spi/1.3.1/maven-resolver-spi-1.3.1.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-spi/1.3.1/maven-resolver-spi-1.3.1.pom
 (3 KB at 156.9 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-util/1.3.1/maven-resolver-util-1.3.1.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-util/1.3.1/maven-resolver-util-1.3.1.pom
 (3 KB at 177.3 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-impl/1.3.1/maven-resolver-impl-1.3.1.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/resolver/maven-resolver-impl/1.3.1/maven-resolver-impl-1.3.1.pom
 (4 KB at 226.5 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/slf4j/slf4j-api/1.7.25/slf4j-api-1.7.25.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/slf4j/slf4j-api/1.7.25/slf4j-api-1.7.25.pom
 (4 KB at 249.5 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/commons-io/commons-io/2.6/commons-io-2.6.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/commons-io/commons-io/2.6/commons-io-2.6.pom
 (14 KB at 870.1 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/com/google/inject/guice/4.2.1/guice-4.2.1.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/com/google/inject/guice/4.2.1/guice-4.2.1.pom
 (11 KB at 563.1 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/com/google/inject/guice-parent/4.2.1/guice-parent-4.2.1.pom
[INFO] Downloaded: 

[jira] [Commented] (LOG4J2-2646) Update MongoDB 3 driver from 3.10.1 to 3.10.2

[ASF subversion and git services (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2646?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875602#comment-16875602
 ] 

ASF subversion and git services commented on LOG4J2-2646:
-

Commit 301773c827629becb8d0a6561ec11cedd2c8be68 in logging-log4j2's branch 
refs/heads/master from Gary Gregory
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=301773c ]

[LOG4J2-2646] Update MongoDB 3 driver from 3.10.1 to 3.10.2.

> Update MongoDB 3 driver from 3.10.1 to 3.10.2
> -
>
> Key: LOG4J2-2646
> URL: https://issues.apache.org/jira/browse/LOG4J2-2646
> Project: Log4j 2
>  Issue Type: New Feature
>  Components: Appenders, MongoDB
>Reporter: Gary Gregory
>Assignee: Gary Gregory
>Priority: Major
>
> Update MongoDB 3 driver from 3.10.1 to 3.10.2.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Closed] (LOG4J2-2646) Update MongoDB 3 driver from 3.10.1 to 3.10.2

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2646?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory closed LOG4J2-2646.

   Resolution: Fixed
Fix Version/s: 2.12.1
   3.0.0

In git master and 2.x-release.

> Update MongoDB 3 driver from 3.10.1 to 3.10.2
> -
>
> Key: LOG4J2-2646
> URL: https://issues.apache.org/jira/browse/LOG4J2-2646
> Project: Log4j 2
>  Issue Type: New Feature
>  Components: Appenders, MongoDB
>Reporter: Gary Gregory
>Assignee: Gary Gregory
>Priority: Major
> Fix For: 3.0.0, 2.12.1
>
>
> Update MongoDB 3 driver from 3.10.1 to 3.10.2.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2560) RollingFileAppender cannot be configured with both OnStartupTriggeringPolicy and createOnDemand="true"

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2560?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2560:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> RollingFileAppender cannot be configured with both OnStartupTriggeringPolicy 
> and createOnDemand="true"
> --
>
> Key: LOG4J2-2560
> URL: https://issues.apache.org/jira/browse/LOG4J2-2560
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Appenders
>Affects Versions: 2.11.2
> Environment: Windows 10 Professional x64
>Reporter: Jeff Gullett
>Priority: Minor
> Fix For: 2.12.1
>
>
> When configuring a RollingFileAppender with the createOnDemand="true" 
> property, and adding the OnStartupTriggeringPolicy, the triggering policy is 
> ignored.  Instead, all logs are simply appended to the existing log file.  
> This should be modified to allow rolling logs that are only created on-demand.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2238) Insufficient Permissions Error when Rolling Log Files

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2238?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2238:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> Insufficient Permissions Error when Rolling Log Files
> -
>
> Key: LOG4J2-2238
> URL: https://issues.apache.org/jira/browse/LOG4J2-2238
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Appenders
>Affects Versions: 2.9.1
> Environment: CentOS 6.6 (32-bit)
> Java 8u151 (32-bit)
>Reporter: Jeff Gullett
>Priority: Minor
>  Labels: Linux, permissions, unix
> Fix For: 2.12.1
>
>
> I have an application utilizing Log4j2 using a rolling file appender.  Within 
> each appender, I set the log file permissions using the new "filePermissions" 
> attribute to be 644 (rw-r--r--). If I run my application as "root", then try 
> to run as any other user, I receive an error with the text (Note: ... == 
> "org.apache.log4j.core."):
> ERROR RollingFileManager (/var/log/myApp/Info.log) 
> java.io.FileNotFoundException: /var/log/myApp/Info.log (Permission denied) 
> java.io.FileNotFoundException: var/log.myApp/Info.log (Permission denied)
>          at java.io.FileOutputStream.open0 (Native Method)
>          at java.io.FileOutputStream.open(FileOutputStream.java:270)
>          at java.io.FileOutputStream.(FileOutputStream.java:213)
>          at java.io.FileOutputStream.(FileOutputStream.java:133)
>          at 
> ...appender.rolling.RollingFileManager$RollingFileManagerFactory.createManager(RollingFileManager.java:640)
>          at 
> ...appender.rolling.RollingFileManager$RollingFileManagerFactory.createManager(RollingFileManager.java:608)
>          at ...appender.AbstractManager.getManager(AbstractManager.java:113)
>          at 
> ...appender.OutputStreamManager.getManager(OutputStreamManager.java:188)
>          ...
> My configuration file is like the following:
> {code:xml}
> 
> 
>   
>      filePattern="/var/log/myApp/Info%d\{-MM-dd}.%i.log" 
> filePermissions="rw-r--r--">
>       
>         
>         
>         
>       
>       
>         
>           
>         
>       
>     
>   
>   
>     
>       
>     
>   
> 
> {code}
> I have verified that the permissions on "/var/log/myApp" are 777 (rwxrwxrwx). 
>  I have also verified that as a non-root user, I am able to move an existing 
> log file (e.g., "mv Info.log Info_Archive.log" works when running as non-root 
> user, even though running my application as that user results in the 
> aforementioned error).  My expectation is that the file would be moved, a new 
> file created, then the output stream opened.  However, it appears from the 
> error that the output stream is opened, then the log file renamed, and 
> finally a new log file created and opened.  A work-around for this issue is 
> to create log files with 777 permissions, but I don't want to give all users 
> full permission to my log files.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2247) RollingRandomAccessFile appender with DirectWriteRolloverStrategy fails with a NullPointerException when a header is supplied

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2247?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2247:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> RollingRandomAccessFile appender with DirectWriteRolloverStrategy fails with 
> a NullPointerException when a header is supplied
> -
>
> Key: LOG4J2-2247
> URL: https://issues.apache.org/jira/browse/LOG4J2-2247
> Project: Log4j 2
>  Issue Type: Bug
>Affects Versions: 2.9.0, 2.9.1, 2.10.0, 2.11.0
> Environment: The additional note attached to LOG4J2-1928 indicates 
> that the failure happens when a header is supplied. Since a unit test 
> validates that the Appender does work with the DirectWriteRolloverStrategy 
> without a header it must be surmised that this error only happens when a 
> header is supplied.
>Reporter: Andrey Kurilov
>Priority: Critical
> Fix For: 2.12.1
>
>
> See the comment
> https://issues.apache.org/jira/browse/LOG4J2-1928?focusedCommentId=16158414=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-16158414
>  



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2636) No default value for mdcId in SyslogAppender

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2636?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2636:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> No default value for mdcId in SyslogAppender
> 
>
> Key: LOG4J2-2636
> URL: https://issues.apache.org/jira/browse/LOG4J2-2636
> Project: Log4j 2
>  Issue Type: Bug
>Affects Versions: 2.11.2
>Reporter: Filipp Gunbin
>Priority: Major
> Fix For: 2.12.1
>
>
> 1) Main issue
> When Rfc5424Layout is created from configuration, it seems to receive default 
> value:
> {code:java}
> @PluginAttribute(value = "mdcId", defaultString = DEFAULT_MDCID) final String 
> mdcId,{code}
> But SyslogAppender has it with no default:
> {code:java}
> @PluginBuilderAttribute("mdcId")
> private String mdcId;{code}
> It is used in SyslogAppender.build() to create Rfc5424Layout.  So, if I don't 
> specify "mdcId" attribute in " config element, I get this exception:
> {quote}ERROR StatusLogger Could not create plugin of type class 
> org.apache.logging.log4j.core.appender.SyslogAppender for element Syslog: 
> java.lang.IllegalArgumentException: No structured id name was supplied 
> java.lang.IllegalArgumentException: No structured id name was supplied at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:146)
>  at 
> org.apache.logging.log4j.message.StructuredDataId.(StructuredDataId.java:130)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.(Rfc5424Layout.java:142)
>  at 
> org.apache.logging.log4j.core.layout.Rfc5424Layout.createLayout(Rfc5424Layout.java:672)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:117)
>  at 
> org.apache.logging.log4j.core.appender.SyslogAppender$Builder.build(SyslogAppender.java:50)
> {quote}
> 2) Documentation doesn't mention mdcId of SyslogAppender at all: 
> [https://logging.apache.org/log4j/2.x/manual/appenders.html#SyslogAppender]
> If I build site locally with "mvn site" in 2.11.2, it's not there either.
> 3) Commit ce1183629fe89625a77872c7153853e7774502a6 
> (https://issues.apache.org/jira/browse/LOG4J2-922) which introduces default 
> value for mdcId in Rfc5424Layout has this code:
> {code:java}
> this.mdcId = id == null ? DEFAULT_MDCID : id;         
> this.mdcSdId = new StructuredDataId(mdcId, enterpriseNumber, null, 
> null);{code}
> While "this.mdcId" is set in first line, the argument (not class member) 
> mdcId is used in the second line.  Maybe argument mdcId should be used in the 
> first line instead of "id"?  Maybe this.mdcId should be used in the second 
> line instead of argument mdcId? I'm not familiar with the code enough to tell 
> for sure, it just feels suspicious to me.
> Thanks.
>  



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-1630) Unit of Work Logging

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-1630?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-1630:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> Unit of Work Logging
> 
>
> Key: LOG4J2-1630
> URL: https://issues.apache.org/jira/browse/LOG4J2-1630
> Project: Log4j 2
>  Issue Type: Story
>  Components: API, Core, Filters
>Affects Versions: 2.7
>Reporter: Remko Popma
>Priority: Major
> Fix For: 2.12.1
>
>
> h3. Intent
> Provide a way to filter log events, where the decision on whether to discard 
> the message or actually log them cannot be made until after the application 
> has already logged the message.
> h3. Motivation
> In many systems, particularly event processing applications, log files 
> contain a lot of repetitive log messages. Suppose an application needs to do 
> some calculation to decide whether or not to react to some event, and a lot 
> of detail is logged during this calculation. Imagine that 99% of the time, 
> the application decides to take no action. Once the application arrived at 
> that conclusion it would be nice if we could go back and undo all the 
> detailed logging and print a summary instead. When the application _does_ 
> decide to take some action, however, we _do_ want the detailed log messages. 
> A Unit of Work for logging would allow us to group a set of log messages and 
> either discard them or log them together. (Inspired by Martin Fowler's [Unit 
> of Work|http://martinfowler.com/eaaCatalog/unitOfWork.html] pattern.)
> This should result in log files where a lot of the "uninteresting" logging is 
> filtered out, significantly reducing the amount of data logged.
> Some applications do this in an ad hoc manner, for example by passing a 
> Collection to its components, where these components can add log message 
> strings to this Collection. When the discard/retain decision is made, the 
> application then either clears the Collection or logs the contents of the 
> Collection. This works, but having to pass the Collection down the component 
> tree is clunky and the result often omits details like logger name, timestamp 
> and other details that come for free with normal logging. Log4j can provide a 
> reusable and less intrusive way to accomplish this.
> h3. How it works
> There would need to be some API for the application to mark the _start_ of 
> the unit of work, and some API to signal whether the log messages that are 
> part of that unit of work need to be _discarded_ or _logged_ (retained).
> Not all logging that occurs after a unit of work was started is part of that 
> unit of work. The application may want some messages to be logged regardless 
> of whether the unit of work was discarded or not. There needs to be a 
> flexible way (or multiple ways) to include or exclude logging statements from 
> the unit of work. 
> The application may also designate multiple units of work, which may be 
> sequential, nested or partially overlapping. Each unit of work may define its 
> own rules for which log messages are considered included in or excluded from 
> the unit of work.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2235) Add ThrowableFormatOptions "COLLAPSE"

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2235?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2235:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> Add ThrowableFormatOptions "COLLAPSE"
> -
>
> Key: LOG4J2-2235
> URL: https://issues.apache.org/jira/browse/LOG4J2-2235
> Project: Log4j 2
>  Issue Type: Improvement
>  Components: Layouts
>Affects Versions: 2.10.0
>Reporter: Dave Brosius
>Priority: Minor
> Fix For: 2.12.1
>
>
> Given that stack traces get out of hand when you have things like spring, 
> hibernate, jersey etc, it would be nice to add an option like "COLLAPSE" that 
> works similar to how you can pass in ignorePackages.
>  
> so that if you have a run of stacktraces that all come from the same package 
> prefix, and you specified that that package name be part of a new 
> collapsePackage set, then only the first stacktrace in that list would be 
> shown, followed by the caller into that series of stack traces. That way you 
> can tell that spring was involved, for instance, but you wouldn't have to see 
> 15 stacktrace elements of spring junk that you aren't interested in.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2509) Allow a JDBC Appender to truncate strings to match a table's metadata column length limit

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2509?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2509:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> Allow a JDBC Appender to truncate strings to match a table's metadata column 
> length limit
> -
>
> Key: LOG4J2-2509
> URL: https://issues.apache.org/jira/browse/LOG4J2-2509
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Appenders
>Reporter: Gary Gregory
>Assignee: Gary Gregory
>Priority: Major
> Fix For: 3.0.0, 2.12.1
>
>
> Allow a JDBC Appender to truncate strings to match a table's metadata column 
> length limit.
> Some databases like MySQL can be configured to cause SQL INSERT statements to 
> fail when data for a column exceeds the length of a column definition.
> In the case of MySQL 8, this is the default configuration, and asking a DB 
> admin to change this to accommodate an application is not reasonable.
> This feature would add a new attribute on the {{JdbcAppender}} called 
> {{truncateStrings}} which would do so. This would be set to true by default 
> for a smooth initial impression.
>  



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2505) Let JDBC PoolingDriverConnectionSource with Apache Commons DBCP configure a PoolableConnectionFactory

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2505?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2505:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> Let JDBC PoolingDriverConnectionSource with Apache Commons DBCP configure a 
> PoolableConnectionFactory
> -
>
> Key: LOG4J2-2505
> URL: https://issues.apache.org/jira/browse/LOG4J2-2505
> Project: Log4j 2
>  Issue Type: Improvement
>Reporter: Gary Gregory
>Assignee: Gary Gregory
>Priority: Major
> Fix For: 3.0.0, 2.12.1
>
>
> Let JDBC Appender's {{PoolingDriverConnectionSource}} with Apache Commons 
> DBCP configure a Commons DBCP {{PoolableConnectionFactory}}.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-2461) Add Automatic-Module-Name to the Manifest

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-2461?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-2461:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> Add Automatic-Module-Name to the Manifest
> -
>
> Key: LOG4J2-2461
> URL: https://issues.apache.org/jira/browse/LOG4J2-2461
> Project: Log4j 2
>  Issue Type: Improvement
>  Components: API
>Affects Versions: 2.11.1
>Reporter: Jeff Gullett
>Priority: Minor
> Fix For: 2.12.1
>
>
> Some tools (Eclipse, Javadoc) don't cleanly support multi-release JAR files.  
> These tools report an error when trying to reference the log4j-api module 
> using the name org.apache.logging.log4j.  Adding this module name to the JAR 
> manifest allows these tools to operate on the JAR despite not correctly 
> locating the module-info.java file.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Updated] (LOG4J2-1990) ConcurrentModificationException logging a parameter of type Map

[Gary Gregory (JIRA)]

 [ 
https://issues.apache.org/jira/browse/LOG4J2-1990?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Gary Gregory updated LOG4J2-1990:
-
Fix Version/s: (was: 2.12.0)
   2.12.1

> ConcurrentModificationException logging a parameter of type Map 
> 
>
> Key: LOG4J2-1990
> URL: https://issues.apache.org/jira/browse/LOG4J2-1990
> Project: Log4j 2
>  Issue Type: Bug
>  Components: Core
>Affects Versions: 2.8.2
>Reporter: Philippe Mouawad
>Priority: Major
> Fix For: 2.12.1
>
> Attachments: LOG4J2-1990.patch
>
>
> Hello,
> Working with current JMeter trunk and:
> *  attached test plan 
> * org.apache.jmeter.protocol.http.control.CacheManager level set to debug in 
> log4j2.xml in bin folder
> I get:
> {code:none}
> java.util.concurrent.ExecutionException: 
> java.util.ConcurrentModificationException
>   at java.util.concurrent.FutureTask.report(FutureTask.java:122) 
> ~[?:1.8.0_121]
>   at java.util.concurrent.FutureTask.get(FutureTask.java:192) 
> ~[?:1.8.0_121]
>   at 
> org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.downloadPageResources(HTTPSamplerBase.java:1349)
>  [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.resultProcessing(HTTPSamplerBase.java:1657)
>  [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.protocol.http.sampler.HTTPAbstractImpl.resultProcessing(HTTPAbstractImpl.java:519)
>  [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.protocol.http.sampler.HTTPHC4Impl.sample(HTTPHC4Impl.java:534)
>  [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.protocol.http.sampler.HTTPSamplerProxy.sample(HTTPSamplerProxy.java:74)
>  [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1189)
>  [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.protocol.http.sampler.HTTPSamplerBase.sample(HTTPSamplerBase.java:1178)
>  [ApacheJMeter_http.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:500)
>  [ApacheJMeter_core.jar:3.3-SNAPSHOT.20170724]
>   at 
> org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) 
> [ApacheJMeter_core.jar:3.3-SNAPSHOT.20170724]
>   at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) 
> [ApacheJMeter_core.jar:3.3-SNAPSHOT.20170724]
>   at java.lang.Thread.run(Thread.java:745) [?:1.8.0_121]
> Caused by: java.util.ConcurrentModificationException
>   at 
> org.apache.commons.collections.map.AbstractLinkedMap$LinkIterator.nextEntry(AbstractLinkedMap.java:560)
>  ~[commons-collections-3.2.2.jar:3.2.2]
>   at 
> org.apache.commons.collections.map.AbstractLinkedMap$EntrySetIterator.next(AbstractLinkedMap.java:428)
>  ~[commons-collections-3.2.2.jar:3.2.2]
>   at 
> org.apache.logging.log4j.message.ParameterFormatter.appendMap(ParameterFormatter.java:569)
>  ~[log4j-api-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.message.ParameterFormatter.appendPotentiallyRecursiveValue(ParameterFormatter.java:505)
>  ~[log4j-api-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:432)
>  ~[log4j-api-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.message.ParameterFormatter.formatMessage2(ParameterFormatter.java:189)
>  ~[log4j-api-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.message.ReusableParameterizedMessage.formatTo(ReusableParameterizedMessage.java:313)
>  ~[log4j-api-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.core.impl.MutableLogEvent.setMessage(MutableLogEvent.java:214)
>  ~[log4j-core-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.core.impl.ReusableLogEventFactory.createEvent(ReusableLogEventFactory.java:81)
>  ~[log4j-core-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:401) 
> [log4j-core-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
>  [log4j-core-2.8.2.jar:2.8.2]
>   at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146) 
> [log4j-core-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091)
>  [log4j-api-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2005)
>  [log4j-api-2.8.2.jar:2.8.2]
>   at 
> org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1876)
>  [log4j-api-2.8.2.jar:2.8.2]
>

[jira] [Commented] (LOG4J2-2646) Update MongoDB 3 driver from 3.10.1 to 3.10.2

[ASF subversion and git services (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2646?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875592#comment-16875592
 ] 

ASF subversion and git services commented on LOG4J2-2646:
-

Commit 263220df8d14073994d615481cafb424a328122f in logging-log4j2's branch 
refs/heads/release-2.x from Gary Gregory
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=263220d ]

[LOG4J2-2646] Update MongoDB 3 driver from 3.10.1 to 3.10.2.

> Update MongoDB 3 driver from 3.10.1 to 3.10.2
> -
>
> Key: LOG4J2-2646
> URL: https://issues.apache.org/jira/browse/LOG4J2-2646
> Project: Log4j 2
>  Issue Type: New Feature
>  Components: Appenders, MongoDB
>Reporter: Gary Gregory
>Assignee: Gary Gregory
>Priority: Major
>
> Update MongoDB 3 driver from 3.10.1 to 3.10.2.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Created] (LOG4J2-2646) Update MongoDB 3 driver from 3.10.1 to 3.10.2

[Gary Gregory (JIRA)]

Gary Gregory created LOG4J2-2646:


 Summary: Update MongoDB 3 driver from 3.10.1 to 3.10.2
 Key: LOG4J2-2646
 URL: https://issues.apache.org/jira/browse/LOG4J2-2646
 Project: Log4j 2
  Issue Type: New Feature
  Components: Appenders, MongoDB
Reporter: Gary Gregory
Assignee: Gary Gregory


Update MongoDB 3 driver from 3.10.1 to 3.10.2.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Comment Edited] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875576#comment-16875576
 ] 

Ralph Goers edited comment on LOG4J2-2644 at 6/29/19 7:13 PM:
--

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 Class getCallerClass(final String fqcn, final String pkg) {
return walker.walk(s -> s.dropWhile(f -> !f.getClassName().equals(fqcn)).
dropWhile(f -> f.getClassName().equals(fqcn)).dropWhile(f -> 
!f.getClassName().startsWith(pkg)).

findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{code}
 

while JUL uses
{code:java}
static final class CallerFinder implements Predicate {
private static final StackWalker WALKER;
static {
final PrivilegedAction 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 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.go...@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|

[jira] [Comment Edited] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875576#comment-16875576
 ] 

Ralph Goers edited comment on LOG4J2-2644 at 6/29/19 7:11 PM:
--

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 Class getCallerClass(final String fqcn, final String pkg) {
return walker.walk(s -> s.dropWhile(f -> !f.getClassName().equals(fqcn)).
dropWhile(f -> f.getClassName().equals(fqcn)).dropWhile(f -> 
!f.getClassName().startsWith(pkg)).

findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{code}
 

while JUL uses
{code:java}
static final class CallerFinder implements Predicate {
private static final StackWalker WALKER;
static {
final PrivilegedAction 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 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 Class getCallerClass(final int depth) {
;
return walker.walk(s -> 
s.skip(depth).findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{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.go...@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|

[jira] [Comment Edited] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875576#comment-16875576
 ] 

Ralph Goers edited comment on LOG4J2-2644 at 6/29/19 7:11 PM:
--

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 Class getCallerClass(final String fqcn, final String pkg) {
return walker.walk(s -> s.dropWhile(f -> !f.getClassName().equals(fqcn)).
dropWhile(f -> f.getClassName().equals(fqcn)).dropWhile(f -> 
!f.getClassName().startsWith(pkg)).

findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{code}
 

while JUL uses
{code:java}
static final class CallerFinder implements Predicate {
private static final StackWalker WALKER;
static {
final PrivilegedAction 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 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 
using 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 Class getCallerClass(final int depth) {
;
return walker.walk(s -> 
s.skip(depth).findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{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.go...@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|

[jira] [Comment Edited] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875576#comment-16875576
 ] 

Ralph Goers edited comment on LOG4J2-2644 at 6/29/19 7:10 PM:
--

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 Class getCallerClass(final String fqcn, final String pkg) {
return walker.walk(s -> s.dropWhile(f -> !f.getClassName().equals(fqcn)).
dropWhile(f -> f.getClassName().equals(fqcn)).dropWhile(f -> 
!f.getClassName().startsWith(pkg)).

findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{code}
 

while JUL uses
{code:java}
static final class CallerFinder implements Predicate {
private static final StackWalker WALKER;
static {
final PrivilegedAction 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 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 Log4j 3 using the new builder pattern using 
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 Class getCallerClass(final int depth) {
;
return walker.walk(s -> 
s.skip(depth).findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{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.go...@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|

Build failed in Jenkins: Log4j 2 3.x #442

[Apache Jenkins Server]

See 


Changes:

[rgoers] LOG4J2-2639 - Pass location information

--
[...truncated 101.22 KB...]
[INFO] 
[INFO] Building Apache Log4j API Java 9 support 3.0.0-SNAPSHOT
[INFO] 
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-toolchains-plugin/1.1/maven-toolchains-plugin-1.1.pom
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-toolchains-plugin/1.1/maven-toolchains-plugin-1.1.pom
 (4 KB at 6.4 KB/sec)
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-plugins/26/maven-plugins-26.pom
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-plugins/26/maven-plugins-26.pom
 (12 KB at 18.6 KB/sec)
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-toolchains-plugin/1.1/maven-toolchains-plugin-1.1.jar
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-toolchains-plugin/1.1/maven-toolchains-plugin-1.1.jar
 (25 KB at 37.1 KB/sec)
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-surefire-plugin/2.13/maven-surefire-plugin-2.13.pom
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-surefire-plugin/2.13/maven-surefire-plugin-2.13.pom
 (6 KB at 8.8 KB/sec)
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/surefire/surefire/2.13/surefire-2.13.pom
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/surefire/surefire/2.13/surefire-2.13.pom
 (17 KB at 19.7 KB/sec)
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-surefire-plugin/2.13/maven-surefire-plugin-2.13.jar
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-surefire-plugin/2.13/maven-surefire-plugin-2.13.jar
 (31 KB at 33.5 KB/sec)
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-assembly-plugin/3.1.0/maven-assembly-plugin-3.1.0.pom
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-assembly-plugin/3.1.0/maven-assembly-plugin-3.1.0.pom
 (16 KB at 22.5 KB/sec)
[INFO] Downloading: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-assembly-plugin/3.1.0/maven-assembly-plugin-3.1.0.jar
[INFO] Downloaded: 
https://repository.apache.org/content/repositories/releases/org/apache/maven/plugins/maven-assembly-plugin/3.1.0/maven-assembly-plugin-3.1.0.jar
 (236 KB at 266.3 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-core/3.6.0/maven-core-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-core/3.6.0/maven-core-3.6.0.pom
 (9 KB at 328.8 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven/3.6.0/maven-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven/3.6.0/maven-3.6.0.pom
 (24 KB at 1461.2 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-model/3.6.0/maven-model-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-model/3.6.0/maven-model-3.6.0.pom
 (4 KB at 224.5 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/codehaus/plexus/plexus-utils/3.2.0/plexus-utils-3.2.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/codehaus/plexus/plexus-utils/3.2.0/plexus-utils-3.2.0.pom
 (5 KB at 336.4 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/codehaus/plexus/plexus/5.1/plexus-5.1.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/codehaus/plexus/plexus/5.1/plexus-5.1.pom
 (22 KB at 1465.1 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-settings/3.6.0/maven-settings-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-settings/3.6.0/maven-settings-3.6.0.pom
 (2 KB at 119.3 KB/sec)
[INFO] Downloading: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-settings-builder/3.6.0/maven-settings-builder-3.6.0.pom
[INFO] Downloaded: 
https://repo.maven.apache.org/maven2/org/apache/maven/maven-settings-builder/3.6.0/maven-settings-builder-3.6.0.pom
 (3 KB at 162.4 KB/sec)
[INFO] Downloading: 

[jira] [Commented] (LOG4J2-2639) Allow log event to be created using the builder pattern.

[ASF subversion and git services (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2639?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875575#comment-16875575
 ] 

ASF subversion and git services commented on LOG4J2-2639:
-

Commit 29b332b6fc20f59df78ae3aeb23a12677a34fe9b in logging-log4j2's branch 
refs/heads/master from Ralph Goers
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=29b332b ]

LOG4J2-2639 - Pass location information


> Allow log event to be created using the builder pattern.
> 
>
> Key: LOG4J2-2639
> URL: https://issues.apache.org/jira/browse/LOG4J2-2639
> Project: Log4j 2
>  Issue Type: Task
>  Components: API
>Affects Versions: 3.0.0
>Reporter: Ralph Goers
>Priority: Major
>  Time Spent: 6h 40m
>  Remaining Estimate: 0h
>
> In some cases it would be convenient to create log events using a builder 
> pattern. One advantage of this approach is that it would allow the location 
> information to be more easily provided.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

[jira] [Commented] (LOG4J2-2644) Logging with location information is considerably slower than logging with location information in java.util.logging

[Ralph Goers (JIRA)]

[ 
https://issues.apache.org/jira/browse/LOG4J2-2644?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16875576#comment-16875576
 ] 

Ralph Goers commented on LOG4J2-2644:
-

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 Class getCallerClass(final String fqcn, final String pkg) {
return walker.walk(s -> s.dropWhile(f -> !f.getClassName().equals(fqcn)).
dropWhile(f -> f.getClassName().equals(fqcn)).dropWhile(f -> 
!f.getClassName().startsWith(pkg)).

findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{code}
 

while JUL uses
{code:java}
static final class CallerFinder implements Predicate {
private static final StackWalker WALKER;
static {
final PrivilegedAction 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 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 Log4j 3 using the new builder pattern using 
logger.atInfo().withLocation().log(msg)

 
||Java Version||Elapsed Time||
|java 8|43.028s|
|java 11|25.548s|

The Java 11 version uses
{code:java}
public Class getCallerClass(final int depth) {
;
return walker.walk(s -> 
s.skip(depth).findFirst()).map(StackWalker.StackFrame::getDeclaringClass).orElse(null);
}{code}
with a depth value of 2. After fixing a bug I got results of
||Method||Elapsed||
|log4j2_with_method|10.321s|

Which, of course and as one would expect, is a dramatic improvement.

 

 

> 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
>
> according to https://logging.apache.org/log4j/2.x/performance.html logging
> with location information should be roughly the same performance for JUL
>