This is an automated email from the ASF dual-hosted git repository. pkarwasz pushed a commit to branch 2.x in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
The following commit(s) were added to refs/heads/2.x by this push: new 3709962553 Improve performance and avoid memory consumption if logging primitive arrays as parameters (#3645) 3709962553 is described below commit 3709962553ddc27774163eb77845b0a47a7b9684 Author: magicwerk <magicw...@gmail.com> AuthorDate: Tue May 6 23:01:49 2025 +0200 Improve performance and avoid memory consumption if logging primitive arrays as parameters (#3645) Current implementation: Method ParameterFormatter.appendArray() delegats to java.util.Arrays.toString() which then allocates a new StringBuilder to return a String which is then added to the existing StringBuilder. Improved implementation: For all primitive types, a method like ParameterFormatter.appendArray(int[], StringBuilder) has been added which is called by ParameterFormatter.appendArray() and avoids the unnecessary object creation. * review comments --- .../log4j/message/ParameterFormatterTest.java | 39 ++++-- .../logging/log4j/message/ParameterFormatter.java | 149 +++++++++++++++++++-- .../log4j/message/ParameterFormatterBenchmark.java | 38 +++++- .../.2.x.x/3645_speedup_array_logging.xml | 10 ++ 4 files changed, 215 insertions(+), 21 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 70194a265b..e4988f4141 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.Arrays; 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.ListStatusListener; 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 @@ class ParameterFormatterTest { }; } + @Test + void testIdentityToString() { + final List<Object> 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<Object> list = new ArrayList<>(); @@ -172,15 +186,22 @@ class ParameterFormatterTest { assertThat(actual).isEqualTo(expected); } - @Test - void testIdentityToString() { - final List<Object> 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<Arguments> 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 0e990894c0..551f02c7f7 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 @@ final class ParameterFormatter { } } - // 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 @@ final class ParameterFormatter { private static void appendArray( final Object o, final StringBuilder str, final Set<Object> 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<Object> effectiveDejaVu = getOrCreateDejaVu(dejaVu); @@ -643,4 +643,133 @@ final class ParameterFormatter { } 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 fce78e8843..846f3cc2c6 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 @@ import org.openjdk.jmh.annotations.State; /** * 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 @@ public class ParameterFormatterBenchmark { 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 0000000000..dd1d15b6a4 --- /dev/null +++ b/src/changelog/.2.x.x/3645_speedup_array_logging.xml @@ -0,0 +1,10 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" + xmlns="https://logging.apache.org/xml/ns" + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd" + type="fixed"> + <issue id="3645" link="https://github.com/apache/logging-log4j2/pull/3645"/> + <description format="asciidoc"> + Improve performance and avoid memory consumption if logging primitive arrays as parameters + </description> +</entry>