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 70194a265b9..e4988f41417 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 @@ -23,6 +23,7 @@ import java.util.Collections; import java.util.List; import java.util.stream.Collectors; +import java.util.stream.Stream; import org.apache.logging.log4j.Level; import org.apache.logging.log4j.message.ParameterFormatter.MessagePatternAnalysis; import org.apache.logging.log4j.status.StatusData; @@ -30,6 +31,7 @@ import org.apache.logging.log4j.test.junit.UsingStatusListener; import org.junit.jupiter.api.Test; import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; import org.junit.jupiter.params.provider.CsvSource; import org.junit.jupiter.params.provider.MethodSource; @@ -146,6 +148,18 @@ static Object[][] messageFormattingTestCases() { }; } + @Test + void testIdentityToString() { + final List list = new ArrayList<>(); + list.add(1); + // noinspection CollectionAddedToSelf + list.add(list); + list.add(2); + final String actual = ParameterFormatter.identityToString(list); + final String expected = list.getClass().getName() + "@" + Integer.toHexString(System.identityHashCode(list)); + assertThat(actual).isEqualTo(expected); + } + @Test void testDeepToString() { final List list = new ArrayList<>(); @@ -172,15 +186,22 @@ void testDeepToStringUsingNonRecursiveButConsequentObjects() { assertThat(actual).isEqualTo(expected); } - @Test - void testIdentityToString() { - final List list = new ArrayList<>(); - list.add(1); - // noinspection CollectionAddedToSelf - list.add(list); - list.add(2); - final String actual = ParameterFormatter.identityToString(list); - final String expected = list.getClass().getName() + "@" + Integer.toHexString(System.identityHashCode(list)); + @ParameterizedTest + @MethodSource("deepToStringArgumentsPrimitiveArrays") + void testDeepToStringPrimitiveArrays(Object obj, String expected) { + final String actual = ParameterFormatter.deepToString(obj); assertThat(actual).isEqualTo(expected); } + + static Stream deepToStringArgumentsPrimitiveArrays() { + return Stream.of( + Arguments.of(new byte[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"), + Arguments.of(new short[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"), + Arguments.of(new int[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"), + Arguments.of(new long[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"), + Arguments.of(new float[] {0, 1, 2, 3, 4}, "[0.0, 1.0, 2.0, 3.0, 4.0]"), + Arguments.of(new double[] {0, 1, 2, 3, 4}, "[0.0, 1.0, 2.0, 3.0, 4.0]"), + Arguments.of(new char[] {'a', 'b', 'c'}, "[a, b, c]"), + Arguments.of(new boolean[] {false, true}, "[false, true]")); + } } 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 0e990894c0f..551f02c7f7b 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 @@ -257,12 +257,12 @@ static void formatMessage( } } - // Fast-path for patterns containing no escapes + // Slow-path for patterns containing escapes if (analysis.escapedCharFound) { formatMessageContainingEscapes(buffer, pattern, args, argCount, analysis); } - // Slow-path for patterns containing escapes + // Fast-path for patterns containing no escapes else { formatMessageContainingNoEscapes(buffer, pattern, args, argCount, analysis); } @@ -487,21 +487,21 @@ private static void appendPotentiallyRecursiveValue( private static void appendArray( final Object o, final StringBuilder str, final Set dejaVu, final Class oClass) { if (oClass == byte[].class) { - str.append(Arrays.toString((byte[]) o)); + appendArray((byte[]) o, str); } else if (oClass == short[].class) { - str.append(Arrays.toString((short[]) o)); + appendArray((short[]) o, str); } else if (oClass == int[].class) { - str.append(Arrays.toString((int[]) o)); + appendArray((int[]) o, str); } else if (oClass == long[].class) { - str.append(Arrays.toString((long[]) o)); + appendArray((long[]) o, str); } else if (oClass == float[].class) { - str.append(Arrays.toString((float[]) o)); + appendArray((float[]) o, str); } else if (oClass == double[].class) { - str.append(Arrays.toString((double[]) o)); + appendArray((double[]) o, str); } else if (oClass == boolean[].class) { - str.append(Arrays.toString((boolean[]) o)); + appendArray((boolean[]) o, str); } else if (oClass == char[].class) { - str.append(Arrays.toString((char[]) o)); + appendArray((char[]) o, str); } else { // special handling of container Object[] final Set effectiveDejaVu = getOrCreateDejaVu(dejaVu); @@ -643,4 +643,133 @@ static String identityToString(final Object obj) { } return obj.getClass().getName() + '@' + Integer.toHexString(System.identityHashCode(obj)); } + + /** + * @see Arrays#toString(byte[]) + */ + private static void appendArray(final byte[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } + + /** + * @see Arrays#toString(short[]) + */ + private static void appendArray(final short[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } + + /** + * @see Arrays#toString(int[]) + */ + // package protected to allow access from ParameterFormatterBenchmark + static void appendArray(final int[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } + + /** + * @see Arrays#toString(long[]) + */ + private static void appendArray(final long[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } + + /** + * @see Arrays#toString(float[]) + */ + private static void appendArray(final float[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } + + /** + * @see Arrays#toString(double[]) + */ + private static void appendArray(final double[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } + + /** + * @see Arrays#toString(boolean[]) + */ + private static void appendArray(final boolean[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } + + /** + * @see Arrays#toString(char[]) + */ + private static void appendArray(char[] a, final StringBuilder str) { + int len = a.length; + if (len == 0) { + str.append("[]"); + return; + } + str.append('[').append(a[0]); + for (int i = 1; i < len; i++) { + str.append(", ").append(a[i]); + } + str.append(']'); + } } diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java index fce78e8843f..846f3cc2c65 100644 --- a/log4j-perf-test/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java +++ b/log4j-perf-test/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java @@ -16,6 +16,7 @@ */ package org.apache.logging.log4j.message; +import java.util.Arrays; import java.util.concurrent.TimeUnit; import org.apache.logging.log4j.message.ParameterFormatter.MessagePatternAnalysis; import org.openjdk.jmh.annotations.Benchmark; @@ -28,11 +29,24 @@ /** * This benchmark is not in the perf.jmh package because it tests the package-protected ParameterFormatter class. */ +// ============================== HOW TO RUN THIS TEST: ==================================== +// +// single thread: +// java -jar log4j-perf/target/benchmarks.jar ".*ParameterFormatterBench.*" -f 1 -wi 5 -i 10 +// +// multiple threads (for example, 4 threads): +// java -jar log4j-perf/target/benchmarks.jar ".*ParameterFormatterBench.*" -f 1 -wi 5 -i 10 -t 4 -si true +// +// Usage help: +// java -jar log4j-perf/target/benchmarks.jar -help +// @State(Scope.Benchmark) public class ParameterFormatterBenchmark { - private static final Object[] ARGS = { - "arg1", "arg2", "arg3", "arg4", "arg5", "arg6", "arg7", "arg8", "arg9", "arg10" + "arg1", "arg2", "arg3", "arg4", "arg5", "arg6", "arg7", "arg8", "arg9", "arg10", + }; + private static final int[] INT_ARRAY = { + 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, }; @State(Scope.Thread) @@ -81,4 +95,24 @@ private static int latencyParams(final ThreadState state, final String pattern) ParameterFormatter.formatMessage(state.buffer, pattern, ARGS, state.analysis.placeholderCount, state.analysis); return state.buffer.length(); } + + @Benchmark + @BenchmarkMode(Mode.SampleTime) + @OutputTimeUnit(TimeUnit.NANOSECONDS) + public int appendArrayToString(final ThreadState state) { + StringBuilder buffer = state.buffer; + buffer.setLength(0); + buffer.append(Arrays.toString(INT_ARRAY)); + return state.buffer.length(); + } + + @Benchmark + @BenchmarkMode(Mode.SampleTime) + @OutputTimeUnit(TimeUnit.NANOSECONDS) + public int appendArrayStringBuilder(final ThreadState state) { + StringBuilder buffer = state.buffer; + buffer.setLength(0); + ParameterFormatter.appendArray(INT_ARRAY, buffer); + return state.buffer.length(); + } } diff --git a/src/changelog/.2.x.x/3645_speedup_array_logging.xml b/src/changelog/.2.x.x/3645_speedup_array_logging.xml new file mode 100644 index 00000000000..dd1d15b6a48 --- /dev/null +++ b/src/changelog/.2.x.x/3645_speedup_array_logging.xml @@ -0,0 +1,10 @@ + + + + + Improve performance and avoid memory consumption if logging primitive arrays as parameters + +