Skip to content

Improve performance and avoid memory consumption if logging primitive arrays as parameters #3645

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
May 6, 2025
Merged

Improve performance and avoid memory consumption if logging primitive arrays as parameters #3645

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
9336aa5
speedup-array-logging
magicwerk May 4, 2025
5b4ba2d
Add tests
magicwerk May 4, 2025
e1b6f15
fix formatting
magicwerk May 4, 2025
3494eb4
implement review comments
magicwerk May 5, 2025
d8f7190
review comments
magicwerk May 6, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
39 changes: 30 additions & 9 deletions log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterFormatterTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,13 +23,15 @@
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;
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;

Expand Down Expand Up @@ -146,6 +148,18 @@ static Object[][] messageFormattingTestCases() {
};
}

@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<>();
Expand All @@ -172,15 +186,22 @@ void testDeepToStringUsingNonRecursiveButConsequentObjects() {
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]"));
}
}
149 changes: 139 additions & 10 deletions log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand Down Expand Up @@ -487,21 +487,21 @@ private static void appendPotentiallyRecursiveValue(
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);
Expand Down Expand Up @@ -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(']');
}
}
38 changes: 36 additions & 2 deletions ...perf-test/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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)
Expand Down Expand Up @@ -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();
}
}
10 changes: 10 additions & 0 deletions src/changelog/.2.x.x/3645_speedup_array_logging.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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>