You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by ck...@apache.org on 2021/11/15 17:05:54 UTC
[logging-log4j2] branch master updated: LOG4J2-3189: Improve worst-case NameAbbreviator performance
This is an automated email from the ASF dual-hosted git repository.
ckozak pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/master by this push:
new c90d1ba LOG4J2-3189: Improve worst-case NameAbbreviator performance
c90d1ba is described below
commit c90d1ba01ae5eeff46efd40b6b073f0b166148c3
Author: Carter Kozak <ck...@apache.org>
AuthorDate: Tue Aug 3 15:19:35 2021 -0400
LOG4J2-3189: Improve worst-case NameAbbreviator performance
Previously the entire input string was written to the output
buffer, then small sections were deleted or replaced within that
string. This meant that for each section that was abbreviated,
nearly all following characters from subsequent sections would
be migrated, resulting in O(n^2) performance.
Now we read from the existing input String, and write sections
to the output buffer piece-by-piece. For small strings this may
result in more pointer-hopping (may cost ~tens of nanoseconds) while
larger values with many abbreviated sections are substantially
less expensive. I would expect large "enterprise-grade" class
names to perform better than previously.
Note that the new approach may result in multiple StringBuilder
resize operations in the worst case, where previously writing
the original string to the output would have caused it to grow
all at once. In most cases we attempt to initialize builders
with a reasonable size, so I opted not to add an `ensureCapacity`
given the estimated size may be substantially larger than we need.
---
.../log4j/core/pattern/NameAbbreviator.java | 83 ++++++++++----------
.../perf/jmh/NamePatternConverterBenchmark.java | 90 ++++++++++++++++++++++
src/changes/changes.xml | 3 +
3 files changed, 132 insertions(+), 44 deletions(-)
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NameAbbreviator.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NameAbbreviator.java
index 869e85b..42f2b64 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NameAbbreviator.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NameAbbreviator.java
@@ -259,7 +259,7 @@ public abstract class NameAbbreviator {
/**
* Fragment of an pattern abbreviator.
*/
- private static class PatternAbbreviatorFragment {
+ private static final class PatternAbbreviatorFragment {
/**
* Count of initial characters of element to output.
*/
@@ -278,7 +278,7 @@ public abstract class NameAbbreviator {
* @param ellipsis character to represent elimination of characters,
* '\0' if no ellipsis is desired.
*/
- public PatternAbbreviatorFragment(
+ PatternAbbreviatorFragment(
final int charCount, final char ellipsis) {
this.charCount = charCount;
this.ellipsis = ellipsis;
@@ -287,40 +287,41 @@ public abstract class NameAbbreviator {
/**
* Abbreviate element of name.
*
- * @param buf buffer to receive element.
- * @param startPos starting index of name element.
- * @return starting index of next element.
+ * @param input input string which is being written to the output {@code buf}.
+ * @param inputIndex starting index of name element in the {@code input} string.
+ * @param buf buffer to receive element.
+ * @return starting index of next element.
*/
- public int abbreviate(final StringBuilder buf, final int startPos) {
- final int start = (startPos < 0) ? 0 : startPos;
- final int max = buf.length();
- int nextDot = -1;
- for (int i = start; i < max; i++) {
- if (buf.charAt(i) == '.') {
- nextDot = i;
- break;
- }
+ int abbreviate(final String input, final int inputIndex, final StringBuilder buf) {
+ // Note that indexOf(char) performs worse than indexOf(String) on pre-16 JREs
+ // due to missing intrinsics for the character implementation. The difference
+ // is a few nanoseconds in most cases, so we opt to give the jre as much
+ // information as possible for best performance on new runtimes, with the
+ // possibility that such optimizations may be back-ported.
+ // See https://bugs.openjdk.java.net/browse/JDK-8173585
+ int nextDot = input.indexOf('.', inputIndex);
+ if (nextDot < 0) {
+ buf.append(input, inputIndex, input.length());
+ return nextDot;
}
- if (nextDot != -1) {
- if (nextDot - startPos > charCount) {
- buf.delete(startPos + charCount, nextDot);
- nextDot = startPos + charCount;
-
- if (ellipsis != '\0') {
- buf.insert(nextDot, ellipsis);
- nextDot++;
- }
+ if (nextDot - inputIndex > charCount) {
+ buf.append(input, inputIndex, inputIndex + charCount);
+ if (ellipsis != '\0') {
+ buf.append(ellipsis);
}
- nextDot++;
+ buf.append('.');
+ } else {
+ // Include the period to reduce interactions with the buffer
+ buf.append(input, inputIndex, nextDot + 1);
}
- return nextDot;
+ return nextDot + 1;
}
}
/**
* Pattern abbreviator.
*/
- private static class PatternAbbreviator extends NameAbbreviator {
+ private static final class PatternAbbreviator extends NameAbbreviator {
/**
* Element abbreviation patterns.
*/
@@ -331,14 +332,13 @@ public abstract class NameAbbreviator {
*
* @param fragments element abbreviation patterns.
*/
- public PatternAbbreviator(final List<PatternAbbreviatorFragment> fragments) {
+ PatternAbbreviator(final List<PatternAbbreviatorFragment> fragments) {
if (fragments.isEmpty()) {
throw new IllegalArgumentException(
"fragments must have at least one element");
}
- this.fragments = new PatternAbbreviatorFragment[fragments.size()];
- fragments.toArray(this.fragments);
+ this.fragments = fragments.toArray(new PatternAbbreviatorFragment[0]);
}
/**
@@ -349,22 +349,17 @@ public abstract class NameAbbreviator {
*/
@Override
public void abbreviate(final String original, final StringBuilder destination) {
- //
- // all non-terminal patterns are executed once
- //
- int pos = destination.length();
- final int max = pos + original.length();
-
- destination.append(original);
-
- int fragmentIndex = 0;
- while (pos < max && pos >= 0) {
- pos = fragments[fragmentIndex].abbreviate(destination, pos);
- // last pattern in executed repeatedly
- if (fragmentIndex < fragments.length - 1) {
- fragmentIndex++;
- }
+ // non-terminal patterns are executed once
+ int originalIndex = 0;
+ int iteration = 0;
+ int originalLength = original.length();
+ while (originalIndex >= 0 && originalIndex < originalLength) {
+ originalIndex = fragment(iteration++).abbreviate(original, originalIndex, destination);
}
}
+
+ PatternAbbreviatorFragment fragment(int index) {
+ return fragments[Math.min(index, fragments.length - 1)];
+ }
}
}
diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/NamePatternConverterBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/NamePatternConverterBenchmark.java
new file mode 100644
index 0000000..36b8a77
--- /dev/null
+++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/NamePatternConverterBenchmark.java
@@ -0,0 +1,90 @@
+package org.apache.logging.log4j.perf.jmh;
+
+import org.apache.logging.log4j.core.AbstractLogEvent;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.pattern.LoggerPatternConverter;
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.BenchmarkMode;
+import org.openjdk.jmh.annotations.Fork;
+import org.openjdk.jmh.annotations.Measurement;
+import org.openjdk.jmh.annotations.Mode;
+import org.openjdk.jmh.annotations.OutputTimeUnit;
+import org.openjdk.jmh.annotations.Param;
+import org.openjdk.jmh.annotations.Scope;
+import org.openjdk.jmh.annotations.Setup;
+import org.openjdk.jmh.annotations.State;
+import org.openjdk.jmh.annotations.Threads;
+import org.openjdk.jmh.annotations.Warmup;
+
+import java.util.concurrent.TimeUnit;
+
+/**
+ * Tests Log4j2 NamePatternConverter's performance.<br>
+ *
+ * How to run these benchmarks:<br>
+ *
+ * Single thread:<br>
+ * <pre>java -jar log4j-perf/target/benchmarks.jar ".*NamePatternConverterBenchmark.*" -f 1 -wi 2 -i 3 -r 3s -jvmArgs '-server -XX:+AggressiveOpts'</pre>
+ *
+ * Multiple threads (for example, 4 threads):<br>
+ * <pre>java -jar log4j-perf/target/benchmarks.jar ".*NamePatternConverterBenchmark.*" -f 1 -wi 4 -i 20 -t 4 -si true</pre>
+ *
+ * Usage help:<br>
+ * <pre>java -jar log4j-perf/target/benchmarks.jar -help</pre>
+ */
+@Fork(1)
+@Threads(1)
+@Warmup(iterations = 3, time = 3)
+@Measurement(iterations = 4, time = 3)
+public class NamePatternConverterBenchmark {
+
+ @State(Scope.Benchmark)
+ public static class ExecutionPlan {
+ @Param({
+ "org.bogus.hokus.pokus.org.bogus.hokus.pokus.org.bogus.hokus.pokus.RetroEncabulatorFactorySingleton",
+ "org.bogus.hokus.pokus.Clazz1",
+ "com.bogus.hokus.pokus.Clazz2",
+ "edu.bogus.hokus.pokus.a.Clazz3",
+ "de.bogus.hokus.b.Clazz4",
+ "jp.bogus.c.Clazz5",
+ "cn.d.Clazz6"
+ })
+ String className;
+ LogEvent event;
+ private final ThreadLocal<StringBuilder> destination = ThreadLocal.withInitial(StringBuilder::new);
+
+ final LoggerPatternConverter converter = LoggerPatternConverter.newInstance(new String[] {"1."});
+
+ @Setup
+ public void setup() {
+ event = new BenchmarkLogEvent(className);
+ }
+
+ StringBuilder destination() {
+ StringBuilder result = destination.get();
+ result.setLength(0);
+ return result;
+ }
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.AverageTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public void benchNamePatternConverter(ExecutionPlan plan) {
+ plan.converter.format(plan.event, plan.destination());
+ }
+
+ private static class BenchmarkLogEvent extends AbstractLogEvent {
+ private final String loggerName;
+
+ BenchmarkLogEvent(String loggerName) {
+ this.loggerName = loggerName;
+ }
+
+ @Override
+ public String getLoggerName() {
+ return loggerName;
+ }
+ }
+
+}
\ No newline at end of file
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index 1e6fe4b..58717d3 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -170,6 +170,9 @@
</release>
<release version="2.15.0" date="2021-MM-DD" description="GA Release 2.15.0">
<!-- ADDS -->
+ <action issue="LOG4J2-3189" dev="ckozak" type="add">
+ Improve NameAbbreviator worst-case performance.
+ </action>
<action issue="LOG4J2-3170" dev="vy" type="add" due-to="Gareth Smith">
Make CRLF/HTML encoding run in O(n) worst-case time, rather than O(n^2).
</action>