[
https://issues.apache.org/jira/browse/LOG4J2-3115?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17373441#comment-17373441
]
Markus Spann edited comment on LOG4J2-3115 at 7/2/21, 11:21 AM:
----------------------------------------------------------------
A JMH benchmark shows a ~3x improvement with the patch applied compared to the
current implementation.
h4. Results with current state of release-2.x branch:
{noformat}
# JMH version: 1.21
# VM version: JDK 9.0.4, OpenJDK 64-Bit Server VM, 9.0.4+11
# VM invoker: /opt/openJdk/jdk-9.0.4+11/bin/java
# VM options: -server -XX:+AggressiveOpts
# Warmup: <none>
# Measurement: 3 iterations, 3 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark:
org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter
# Run progress: 0,00% complete, ETA 00:00:09
# Fork: 1 of 1
Picked up JAVA_TOOL_OPTIONS: -Doracle.net.tns_admin=/opt/oracle/adm/net/
Iteration 1: 8416659,364 ops/s
Iteration 2: 9176477,095 ops/s
Iteration 3: 8922643,679 ops/s
Result
"org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter":
8838593,379 ±(99.9%) 7057022,029 ops/s [Average]
(min, avg, max) = (8416659,364, 8838593,379, 9176477,095), stdev = 386819,190
CI (99.9%): [1781571,350, 15895615,409] (assumes normal distribution)
# Run complete. Total time: 00:00:09
Benchmark Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter thrpt 3 8838593,379 ±
7057022,029 ops/s
{noformat}
h4. Results with patch applied:
{noformat}
# JMH version: 1.21
# VM version: JDK 9.0.4, OpenJDK 64-Bit Server VM, 9.0.4+11
# VM invoker: /opt/openJdk/jdk-9.0.4+11/bin/java
# VM options: -server -XX:+AggressiveOpts
# Warmup: <none>
# Measurement: 3 iterations, 3 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark:
org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter
# Run progress: 0,00% complete, ETA 00:00:09
# Fork: 1 of 1
Picked up JAVA_TOOL_OPTIONS: -Doracle.net.tns_admin=/opt/oracle/adm/net/
Iteration 1: 22609007,617 ops/s
Iteration 2: 24467053,653 ops/s
Iteration 3: 25138829,367 ops/s
Result
"org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter":
24071630,212 ±(99.9%) 23907417,405 ops/s [Average]
(min, avg, max) = (22609007,617, 24071630,212, 25138829,367), stdev =
1310446,220
CI (99.9%): [164212,808, 47979047,617] (assumes normal distribution)
# Run complete. Total time: 00:00:09
Benchmark Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter thrpt 3 24071630,212 ±
23907417,405 ops/s
{noformat}
h4. Command line
{noformat}
mvn clean install -Dmaven.test.skip=true -D skipTests=true -f log4j-core/pom.xml
mvn clean install -Dmaven.test.skip=true -D skipTests=true -f log4j-perf/pom.xml
java -jar log4j-perf/target/benchmarks.jar -f 1 -wi 0 -i 3 -r 3s -jvmArgs
'-server -XX:+AggressiveOpts' .*NamePatternConverterBenchmark.*
{noformat}
was (Author: spannjp):
A JMH benchmark shows a ~3x improvement with the patch applied compared to the
current implementation.
h4. Results with current state of release-2.x branch:
{noformat}
# JMH version: 1.21
# VM version: JDK 9.0.4, OpenJDK 64-Bit Server VM, 9.0.4+11
# VM invoker: /opt/openJdk/jdk-9.0.4+11/bin/java
# VM options: -server -XX:+AggressiveOpts
# Warmup: <none>
# Measurement: 3 iterations, 3 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark:
org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter
# Run progress: 0,00% complete, ETA 00:00:09
# Fork: 1 of 1
Picked up JAVA_TOOL_OPTIONS: -Doracle.net.tns_admin=/opt/oracle/adm/net/
Iteration 1: 8416659,364 ops/s
Iteration 2: 9176477,095 ops/s
Iteration 3: 8922643,679 ops/s
Result
"org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter":
8838593,379 ±(99.9%) 7057022,029 ops/s [Average]
(min, avg, max) = (8416659,364, 8838593,379, 9176477,095), stdev = 386819,190
CI (99.9%): [1781571,350, 15895615,409] (assumes normal distribution)
# Run complete. Total time: 00:00:09
Benchmark Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter thrpt 3 8838593,379 ±
7057022,029 ops/s
{noformat}
h4. Results with patch applied:
{noformat}
# JMH version: 1.21
# VM version: JDK 9.0.4, OpenJDK 64-Bit Server VM, 9.0.4+11
# VM invoker: /opt/openJdk/jdk-9.0.4+11/bin/java
# VM options: -server -XX:+AggressiveOpts
# Warmup: <none>
# Measurement: 3 iterations, 3 s each
# Timeout: 10 min per iteration
# Threads: 1 thread, will synchronize iterations
# Benchmark mode: Throughput, ops/time
# Benchmark:
org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter
# Run progress: 0,00% complete, ETA 00:00:09
# Fork: 1 of 1
Picked up JAVA_TOOL_OPTIONS: -Doracle.net.tns_admin=/opt/oracle/adm/net/
Iteration 1: 22609007,617 ops/s
Iteration 2: 24467053,653 ops/s
Iteration 3: 25138829,367 ops/s
Result
"org.apache.logging.log4j.perf.jmh.NamePatternConverterBenchmark.benchNamePatternConverter":
24071630,212 ±(99.9%) 23907417,405 ops/s [Average]
(min, avg, max) = (22609007,617, 24071630,212, 25138829,367), stdev =
1310446,220
CI (99.9%): [164212,808, 47979047,617] (assumes normal distribution)
# Run complete. Total time: 00:00:09
Benchmark Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter thrpt 3 24071630,212 ±
23907417,405 ops/s
{noformat}
> Remember previously computed strings in NamePatternConverter
> ------------------------------------------------------------
>
> Key: LOG4J2-3115
> URL: https://issues.apache.org/jira/browse/LOG4J2-3115
> Project: Log4j 2
> Issue Type: Improvement
> Components: Core
> Reporter: Markus Spann
> Priority: Minor
>
> Implementations of {{NamePatternConverter}} are responsible for abbreviating
> logger and class names according to a configured pattern.
> Abbreviation can be quite complex and computationally expensive (consider
> abbreviating x parts of a fully qualified class name to y number of leftmost
> characters).
> Example:
> The pattern {{%logger\{1.}}} abbreviates logger name
> {{org.apache.logging.log4j.core.pattern.NameAbbreviator}} to
> {{o.a.l.l.c.p.NameAbbreviator}}
> The strings to abbreviate (logger and class names) extremely likely stem from
> a limited set of candidates. I would like to suggest that results are cached
> to prevent computation over and over again e.g. in every log statement of a
> logger.
> I have a small patch ready that addresses the issue.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
