This is an automated email from the ASF dual-hosted git repository. vy pushed a commit to branch message-param-formatter-rewrite in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit a996006f6d1fcccd7bd37c4ec5e308ddaf891fb3 Author: Volkan Yazıcı <[email protected]> AuthorDate: Tue Aug 1 15:34:22 2023 +0200 Only track placeholders that correspond to an argument --- .../log4j/message/ParameterFormatterTest.java | 5 +- .../logging/log4j/message/ParameterFormatter.java | 78 +++++++++++++++------- .../log4j/message/ParameterizedMessage.java | 7 +- .../message/ReusableParameterizedMessage.java | 16 ++--- .../log4j/message/ParameterFormatterBenchmark.java | 30 ++++----- 5 files changed, 86 insertions(+), 50 deletions(-) diff --git a/log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterFormatterTest.java b/log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterFormatterTest.java index ef477a129e..6f69bf4e6b 100644 --- a/log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterFormatterTest.java +++ b/log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterFormatterTest.java @@ -21,6 +21,7 @@ import java.util.Arrays; import java.util.Collections; import java.util.List; +import org.apache.logging.log4j.message.ParameterFormatter.MessagePatternAnalysis; import org.junit.jupiter.api.Test; import org.junit.jupiter.params.ParameterizedTest; import org.junit.jupiter.params.provider.CsvSource; @@ -54,7 +55,7 @@ public class ParameterFormatterTest { final String placeholderCharIndicesString, final boolean escapedPlaceholderFound, final String pattern) { - ParameterFormatter.MessagePatternAnalysis analysis = ParameterFormatter.analyzePattern(pattern); + MessagePatternAnalysis analysis = ParameterFormatter.analyzePattern(pattern, placeholderCount); assertThat(analysis.placeholderCount).isEqualTo(placeholderCount); if (placeholderCount > 0) { final int[] placeholderCharIndices = Arrays @@ -73,7 +74,7 @@ public class ParameterFormatterTest { final Object[] args, final int argCount, final String expectedFormattedMessage) { - ParameterFormatter.MessagePatternAnalysis analysis = ParameterFormatter.analyzePattern(pattern); + MessagePatternAnalysis analysis = ParameterFormatter.analyzePattern(pattern, -1); final StringBuilder buffer = new StringBuilder(); ParameterFormatter.formatMessage(buffer, pattern, args, argCount, analysis); String actualFormattedMessage = buffer.toString(); diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java index 58646e5b03..6bd1c00862 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java @@ -18,13 +18,7 @@ package org.apache.logging.log4j.message; import java.time.ZoneId; import java.time.format.DateTimeFormatter; -import java.util.Arrays; -import java.util.Collection; -import java.util.Collections; -import java.util.Date; -import java.util.IdentityHashMap; -import java.util.Map; -import java.util.Set; +import java.util.*; import org.apache.logging.log4j.util.StringBuilders; @@ -82,13 +76,15 @@ final class ParameterFormatter { * </pre> * * @param pattern a message pattern to be analyzed + * @param argCount + * The number of arguments to be formatted. + * For instance, for a parametrized message containing 7 placeholders in the pattern and 4 arguments for formatting, analysis will only need to store the index of the first 4 placeholder characters. + * A negative value indicates no limit. * @return the analysis result */ - static MessagePatternAnalysis analyzePattern(final String pattern) { - final int maxPlaceholderCount = pattern == null ? 0 : pattern.length() >> 1; + static MessagePatternAnalysis analyzePattern(final String pattern, final int argCount) { MessagePatternAnalysis analysis = new MessagePatternAnalysis(); - analysis.placeholderCharIndices = new int[maxPlaceholderCount]; - analyzePattern(pattern, analysis); + analyzePattern(pattern, argCount, analysis); return analysis; } @@ -107,16 +103,22 @@ final class ParameterFormatter { * </pre> * * @param pattern a message pattern to be analyzed + * @param argCount + * The number of arguments to be formatted. + * For instance, for a parametrized message containing 7 placeholders in the pattern and 4 arguments for formatting, analysis will only need to store the index of the first 4 placeholder characters. + * A negative value indicates no limit. * @param analysis an object to store the results - * @return {@code true}, if analysis is successful; {@code false} on insufficient {@link MessagePatternAnalysis#placeholderCharIndices index array} capacity */ - static boolean analyzePattern(final String pattern, final MessagePatternAnalysis analysis) { + static void analyzePattern( + final String pattern, + final int argCount, + final MessagePatternAnalysis analysis) { // Short-circuit if there is nothing interesting final int l; if (pattern == null || (l = pattern.length()) < 2) { analysis.placeholderCount = 0; - return true; + return; } // Count `{}` occurrences that is not escaped, i.e., not `\`-prefixed @@ -131,27 +133,37 @@ final class ParameterFormatter { } else { if (escaped) { escaped = false; - if (c == DELIM_START) { - analysis.escapedCharFound = true; - } } else if (c == DELIM_START && pattern.charAt(i + 1) == DELIM_STOP) { - if (analysis.placeholderCount < analysis.placeholderCharIndices.length) { + if (argCount < 0 || analysis.placeholderCount < argCount) { + analysis.ensurePlaceholderCharIndicesCapacity(argCount); analysis.placeholderCharIndices[analysis.placeholderCount++] = i++; - } else { - return false; + } + // `argCount` is exceeded, skip storing the index + else { + analysis.placeholderCount++; + i++; } } } } - return true; } /** - * @see #analyzePattern(String, MessagePatternAnalysis) + * @see #analyzePattern(String, int, MessagePatternAnalysis) */ static final class MessagePatternAnalysis { + /** + * The size of the {@link #placeholderCharIndices} buffer to be allocated if it is found to be null. + */ + private static final int PLACEHOLDER_CHAR_INDEX_BUFFER_INITIAL_SIZE = 8; + + /** + * The size {@link #placeholderCharIndices} buffer will be extended with if it has found to be insufficient. + */ + private static final int PLACEHOLDER_CHAR_INDEX_BUFFER_SIZE_INCREMENT = 8; + /** * The total number of argument placeholder occurrences. */ @@ -167,6 +179,26 @@ final class ParameterFormatter { */ boolean escapedCharFound; + private void ensurePlaceholderCharIndicesCapacity(final int argCount) { + + // Initialize the index buffer, if necessary + if (placeholderCharIndices == null) { + final int length = Math.max(argCount, PLACEHOLDER_CHAR_INDEX_BUFFER_INITIAL_SIZE); + placeholderCharIndices = new int[length]; + } + + // Extend the index buffer, if necessary + else if (placeholderCount >= placeholderCharIndices.length) { + final int newLength = argCount > 0 + ? argCount + : Math.addExact(placeholderCharIndices.length, PLACEHOLDER_CHAR_INDEX_BUFFER_SIZE_INCREMENT); + final int[] newPlaceholderCharIndices = new int[newLength]; + System.arraycopy(placeholderCharIndices, 0, newPlaceholderCharIndices, 0, placeholderCount); + placeholderCharIndices = newPlaceholderCharIndices; + } + + } + } /** @@ -178,7 +210,7 @@ final class ParameterFormatter { */ static String format(final String pattern, final Object[] args, int argCount) { final StringBuilder result = new StringBuilder(); - final MessagePatternAnalysis analysis = analyzePattern(pattern); + final MessagePatternAnalysis analysis = analyzePattern(pattern, argCount); formatMessage(result, pattern, args, argCount, analysis); return result.toString(); } diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java index ca3f51f156..c789e357b6 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java @@ -129,7 +129,7 @@ public class ParameterizedMessage implements Message, StringBuilderFormattable { public ParameterizedMessage(final String pattern, final Object[] args, final Throwable throwable) { this.args = args; this.pattern = pattern; - this.patternAnalysis = analyzePattern(pattern); + this.patternAnalysis = analyzePattern(pattern, args != null ? args.length : 0); this.throwable = determineThrowable(throwable, this.args, patternAnalysis); } @@ -296,7 +296,10 @@ public class ParameterizedMessage implements Message, StringBuilderFormattable { * @return the number of argument placeholders */ public static int countArgumentPlaceholders(final String pattern) { - return analyzePattern(pattern).placeholderCount; + if (pattern == null) { + return 0; + } + return analyzePattern(pattern, -1).placeholderCount; } /** diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java index deecb2aa07..1b11f003fd 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java @@ -39,7 +39,7 @@ public class ReusableParameterizedMessage implements ReusableMessage, ParameterV private transient ThreadLocal<StringBuilder> buffer; // non-static: LOG4J2-1583 private String messagePattern; - private MessagePatternAnalysis patternAnalysis; + private final MessagePatternAnalysis patternAnalysis = new MessagePatternAnalysis(); private int argCount; private transient Object[] varargs; private transient Object[] params = new Object[MAX_PARAMS]; @@ -123,16 +123,10 @@ public class ReusableParameterizedMessage implements ReusableMessage, ParameterV this.varargs = null; this.messagePattern = messagePattern; this.argCount = argCount; - this.patternAnalysis = analyzePattern(messagePattern, patternAnalysis); + ParameterFormatter.analyzePattern(messagePattern, argCount, patternAnalysis); this.throwable = determineThrowable(args, argCount, patternAnalysis.placeholderCount); } - private static MessagePatternAnalysis analyzePattern(final String pattern, final MessagePatternAnalysis patternAnalysis) { - return (patternAnalysis != null && ParameterFormatter.analyzePattern(pattern, patternAnalysis)) - ? patternAnalysis - : ParameterFormatter.analyzePattern(pattern); - } - private static Throwable determineThrowable(final Object[] args, final int argCount, final int placeholderCount) { if (placeholderCount < argCount) { final Object lastArg = args[argCount - 1]; @@ -346,5 +340,11 @@ public class ReusableParameterizedMessage implements ReusableMessage, ParameterV varargs = null; messagePattern = null; throwable = null; + // Cut down on the memory usage after an analysis with an excessive argument count + final int placeholderCharIndicesMaxLength = 16; + if (patternAnalysis.placeholderCharIndices != null && patternAnalysis.placeholderCharIndices.length > placeholderCharIndicesMaxLength) { + patternAnalysis.placeholderCharIndices = new int[placeholderCharIndicesMaxLength]; + } } + } diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java index 669507d344..05f0a5de18 100644 --- a/log4j-perf/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java +++ b/log4j-perf/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java @@ -47,48 +47,48 @@ public class ParameterFormatterBenchmark { @State(Scope.Thread) public static class ThreadState { - + private final MessagePatternAnalysis analysis = new MessagePatternAnalysis(); - + private final StringBuilder buffer = new StringBuilder(2048); - + public ThreadState() { - analysis.placeholderCharIndices = new int[9]; + analysis.placeholderCharIndices = new int[10]; } - + } @Benchmark @BenchmarkMode(Mode.SampleTime) @OutputTimeUnit(TimeUnit.NANOSECONDS) - public int latency3ParamsVy(final ThreadState state) { - return latencyParamsVy(state, "p1={}, p2={}, p3={}"); + public int latency3Params(final ThreadState state) { + return latencyParams(state, "p1={}, p2={}, p3={}"); } @Benchmark @BenchmarkMode(Mode.SampleTime) @OutputTimeUnit(TimeUnit.NANOSECONDS) - public int latency5ParamsVy(final ThreadState state) { - return latencyParamsVy(state, "p1={}, p2={}, p3={}, p4={}, p5={}"); + public int latency5Params(final ThreadState state) { + return latencyParams(state, "p1={}, p2={}, p3={}, p4={}, p5={}"); } @Benchmark @BenchmarkMode(Mode.SampleTime) @OutputTimeUnit(TimeUnit.NANOSECONDS) - public int latency7ParamsVy(final ThreadState state) { - return latencyParamsVy(state, "p1={}, p2={}, p3={}, p4={}, p5={}, p6={}, p7={}"); + public int latency7Params(final ThreadState state) { + return latencyParams(state, "p1={}, p2={}, p3={}, p4={}, p5={}, p6={}, p7={}"); } @Benchmark @BenchmarkMode(Mode.SampleTime) @OutputTimeUnit(TimeUnit.NANOSECONDS) - public int latency9ParamsVy(final ThreadState state) { - return latencyParamsVy(state, "p1={}, p2={}, p3={}, p4={}, p5={}, p6={}, p7={}, p8={}, p9={}"); + public int latency9Params(final ThreadState state) { + return latencyParams(state, "p1={}, p2={}, p3={}, p4={}, p5={}, p6={}, p7={}, p8={}, p9={}"); } - private static int latencyParamsVy(final ThreadState state, final String pattern) { + private static int latencyParams(final ThreadState state, final String pattern) { state.buffer.setLength(0); - ParameterFormatter.analyzePattern(pattern, state.analysis); + ParameterFormatter.analyzePattern(pattern, -1, state.analysis); ParameterFormatter.formatMessage(state.buffer, pattern, ARGS, state.analysis.placeholderCount, state.analysis); return state.buffer.length(); }
