Skip to content

Commit 3709962

Browse files
magicwerkmagicwerk
authored
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
1 parent 9176b44 commit 3709962

File tree

4 files changed

+215
-21
lines changed

4 files changed

+215
-21
lines changed

‎log4j-api-test/src/test/java/org/apache/logging/log4j/message/ParameterFormatterTest.java

+30-9
Original file line numberDiff line numberDiff line change
@@ -23,13 +23,15 @@
2323
import java.util.Collections;
2424
import java.util.List;
2525
import java.util.stream.Collectors;
26+
import java.util.stream.Stream;
2627
import org.apache.logging.log4j.Level;
2728
import org.apache.logging.log4j.message.ParameterFormatter.MessagePatternAnalysis;
2829
import org.apache.logging.log4j.status.StatusData;
2930
import org.apache.logging.log4j.test.ListStatusListener;
3031
import org.apache.logging.log4j.test.junit.UsingStatusListener;
3132
import org.junit.jupiter.api.Test;
3233
import org.junit.jupiter.params.ParameterizedTest;
34+
import org.junit.jupiter.params.provider.Arguments;
3335
import org.junit.jupiter.params.provider.CsvSource;
3436
import org.junit.jupiter.params.provider.MethodSource;
3537

@@ -146,6 +148,18 @@ static Object[][] messageFormattingTestCases() {
146148
};
147149
}
148150

151+
@Test
152+
void testIdentityToString() {
153+
final List<Object> list = new ArrayList<>();
154+
list.add(1);
155+
// noinspection CollectionAddedToSelf
156+
list.add(list);
157+
list.add(2);
158+
final String actual = ParameterFormatter.identityToString(list);
159+
final String expected = list.getClass().getName() + "@" + Integer.toHexString(System.identityHashCode(list));
160+
assertThat(actual).isEqualTo(expected);
161+
}
162+
149163
@Test
150164
void testDeepToString() {
151165
final List<Object> list = new ArrayList<>();
@@ -172,15 +186,22 @@ void testDeepToStringUsingNonRecursiveButConsequentObjects() {
172186
assertThat(actual).isEqualTo(expected);
173187
}
174188

175-
@Test
176-
void testIdentityToString() {
177-
final List<Object> list = new ArrayList<>();
178-
list.add(1);
179-
// noinspection CollectionAddedToSelf
180-
list.add(list);
181-
list.add(2);
182-
final String actual = ParameterFormatter.identityToString(list);
183-
final String expected = list.getClass().getName() + "@" + Integer.toHexString(System.identityHashCode(list));
189+
@ParameterizedTest
190+
@MethodSource("deepToStringArgumentsPrimitiveArrays")
191+
void testDeepToStringPrimitiveArrays(Object obj, String expected) {
192+
final String actual = ParameterFormatter.deepToString(obj);
184193
assertThat(actual).isEqualTo(expected);
185194
}
195+
196+
static Stream<Arguments> deepToStringArgumentsPrimitiveArrays() {
197+
return Stream.of(
198+
Arguments.of(new byte[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"),
199+
Arguments.of(new short[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"),
200+
Arguments.of(new int[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"),
201+
Arguments.of(new long[] {0, 1, 2, 3, 4}, "[0, 1, 2, 3, 4]"),
202+
Arguments.of(new float[] {0, 1, 2, 3, 4}, "[0.0, 1.0, 2.0, 3.0, 4.0]"),
203+
Arguments.of(new double[] {0, 1, 2, 3, 4}, "[0.0, 1.0, 2.0, 3.0, 4.0]"),
204+
Arguments.of(new char[] {'a', 'b', 'c'}, "[a, b, c]"),
205+
Arguments.of(new boolean[] {false, true}, "[false, true]"));
206+
}
186207
}

‎log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterFormatter.java

+139-10
Original file line numberDiff line numberDiff line change
@@ -257,12 +257,12 @@ static void formatMessage(
257257
}
258258
}
259259

260-
// Fast-path for patterns containing no escapes
260+
// Slow-path for patterns containing escapes
261261
if (analysis.escapedCharFound) {
262262
formatMessageContainingEscapes(buffer, pattern, args, argCount, analysis);
263263
}
264264

265-
// Slow-path for patterns containing escapes
265+
// Fast-path for patterns containing no escapes
266266
else {
267267
formatMessageContainingNoEscapes(buffer, pattern, args, argCount, analysis);
268268
}
@@ -487,21 +487,21 @@ private static void appendPotentiallyRecursiveValue(
487487
private static void appendArray(
488488
final Object o, final StringBuilder str, final Set<Object> dejaVu, final Class<?> oClass) {
489489
if (oClass == byte[].class) {
490-
str.append(Arrays.toString((byte[]) o));
490+
appendArray((byte[]) o, str);
491491
} else if (oClass == short[].class) {
492-
str.append(Arrays.toString((short[]) o));
492+
appendArray((short[]) o, str);
493493
} else if (oClass == int[].class) {
494-
str.append(Arrays.toString((int[]) o));
494+
appendArray((int[]) o, str);
495495
} else if (oClass == long[].class) {
496-
str.append(Arrays.toString((long[]) o));
496+
appendArray((long[]) o, str);
497497
} else if (oClass == float[].class) {
498-
str.append(Arrays.toString((float[]) o));
498+
appendArray((float[]) o, str);
499499
} else if (oClass == double[].class) {
500-
str.append(Arrays.toString((double[]) o));
500+
appendArray((double[]) o, str);
501501
} else if (oClass == boolean[].class) {
502-
str.append(Arrays.toString((boolean[]) o));
502+
appendArray((boolean[]) o, str);
503503
} else if (oClass == char[].class) {
504-
str.append(Arrays.toString((char[]) o));
504+
appendArray((char[]) o, str);
505505
} else {
506506
// special handling of container Object[]
507507
final Set<Object> effectiveDejaVu = getOrCreateDejaVu(dejaVu);
@@ -643,4 +643,133 @@ static String identityToString(final Object obj) {
643643
}
644644
return obj.getClass().getName() + '@' + Integer.toHexString(System.identityHashCode(obj));
645645
}
646+
647+
/**
648+
* @see Arrays#toString(byte[])
649+
*/
650+
private static void appendArray(final byte[] a, final StringBuilder str) {
651+
int len = a.length;
652+
if (len == 0) {
653+
str.append("[]");
654+
return;
655+
}
656+
str.append('[').append(a[0]);
657+
for (int i = 1; i < len; i++) {
658+
str.append(", ").append(a[i]);
659+
}
660+
str.append(']');
661+
}
662+
663+
/**
664+
* @see Arrays#toString(short[])
665+
*/
666+
private static void appendArray(final short[] a, final StringBuilder str) {
667+
int len = a.length;
668+
if (len == 0) {
669+
str.append("[]");
670+
return;
671+
}
672+
str.append('[').append(a[0]);
673+
for (int i = 1; i < len; i++) {
674+
str.append(", ").append(a[i]);
675+
}
676+
str.append(']');
677+
}
678+
679+
/**
680+
* @see Arrays#toString(int[])
681+
*/
682+
// package protected to allow access from ParameterFormatterBenchmark
683+
static void appendArray(final int[] a, final StringBuilder str) {
684+
int len = a.length;
685+
if (len == 0) {
686+
str.append("[]");
687+
return;
688+
}
689+
str.append('[').append(a[0]);
690+
for (int i = 1; i < len; i++) {
691+
str.append(", ").append(a[i]);
692+
}
693+
str.append(']');
694+
}
695+
696+
/**
697+
* @see Arrays#toString(long[])
698+
*/
699+
private static void appendArray(final long[] a, final StringBuilder str) {
700+
int len = a.length;
701+
if (len == 0) {
702+
str.append("[]");
703+
return;
704+
}
705+
str.append('[').append(a[0]);
706+
for (int i = 1; i < len; i++) {
707+
str.append(", ").append(a[i]);
708+
}
709+
str.append(']');
710+
}
711+
712+
/**
713+
* @see Arrays#toString(float[])
714+
*/
715+
private static void appendArray(final float[] a, final StringBuilder str) {
716+
int len = a.length;
717+
if (len == 0) {
718+
str.append("[]");
719+
return;
720+
}
721+
str.append('[').append(a[0]);
722+
for (int i = 1; i < len; i++) {
723+
str.append(", ").append(a[i]);
724+
}
725+
str.append(']');
726+
}
727+
728+
/**
729+
* @see Arrays#toString(double[])
730+
*/
731+
private static void appendArray(final double[] a, final StringBuilder str) {
732+
int len = a.length;
733+
if (len == 0) {
734+
str.append("[]");
735+
return;
736+
}
737+
str.append('[').append(a[0]);
738+
for (int i = 1; i < len; i++) {
739+
str.append(", ").append(a[i]);
740+
}
741+
str.append(']');
742+
}
743+
744+
/**
745+
* @see Arrays#toString(boolean[])
746+
*/
747+
private static void appendArray(final boolean[] a, final StringBuilder str) {
748+
int len = a.length;
749+
if (len == 0) {
750+
str.append("[]");
751+
return;
752+
}
753+
str.append('[').append(a[0]);
754+
for (int i = 1; i < len; i++) {
755+
str.append(", ").append(a[i]);
756+
}
757+
str.append(']');
758+
}
759+
760+
/**
761+
* @see Arrays#toString(char[])
762+
*/
763+
private static void appendArray(char[] a, final StringBuilder str) {
764+
int len = a.length;
765+
if (len == 0) {
766+
str.append("[]");
767+
return;
768+
}
769+
str.append('[').append(a[0]);
770+
for (int i = 1; i < len; i++) {
771+
str.append(", ").append(a[i]);
772+
}
773+
str.append(']');
774+
}
646775
}

‎log4j-perf-test/src/main/java/org/apache/logging/log4j/message/ParameterFormatterBenchmark.java

+36-2
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616
*/
1717
package org.apache.logging.log4j.message;
1818

19+
import java.util.Arrays;
1920
import java.util.concurrent.TimeUnit;
2021
import org.apache.logging.log4j.message.ParameterFormatter.MessagePatternAnalysis;
2122
import org.openjdk.jmh.annotations.Benchmark;
@@ -28,11 +29,24 @@
2829
/**
2930
* This benchmark is not in the perf.jmh package because it tests the package-protected ParameterFormatter class.
3031
*/
32+
// ============================== HOW TO RUN THIS TEST: ====================================
33+
//
34+
// single thread:
35+
// java -jar log4j-perf/target/benchmarks.jar ".*ParameterFormatterBench.*" -f 1 -wi 5 -i 10
36+
//
37+
// multiple threads (for example, 4 threads):
38+
// java -jar log4j-perf/target/benchmarks.jar ".*ParameterFormatterBench.*" -f 1 -wi 5 -i 10 -t 4 -si true
39+
//
40+
// Usage help:
41+
// java -jar log4j-perf/target/benchmarks.jar -help
42+
//
3143
@State(Scope.Benchmark)
3244
public class ParameterFormatterBenchmark {
33-
3445
private static final Object[] ARGS = {
35-
"arg1", "arg2", "arg3", "arg4", "arg5", "arg6", "arg7", "arg8", "arg9", "arg10"
46+
"arg1", "arg2", "arg3", "arg4", "arg5", "arg6", "arg7", "arg8", "arg9", "arg10",
47+
};
48+
private static final int[] INT_ARRAY = {
49+
0, 1, 2, 3, 4, 5, 6, 7, 8, 9,
3650
};
3751

3852
@State(Scope.Thread)
@@ -81,4 +95,24 @@ private static int latencyParams(final ThreadState state, final String pattern)
8195
ParameterFormatter.formatMessage(state.buffer, pattern, ARGS, state.analysis.placeholderCount, state.analysis);
8296
return state.buffer.length();
8397
}
98+
99+
@Benchmark
100+
@BenchmarkMode(Mode.SampleTime)
101+
@OutputTimeUnit(TimeUnit.NANOSECONDS)
102+
public int appendArrayToString(final ThreadState state) {
103+
StringBuilder buffer = state.buffer;
104+
buffer.setLength(0);
105+
buffer.append(Arrays.toString(INT_ARRAY));
106+
return state.buffer.length();
107+
}
108+
109+
@Benchmark
110+
@BenchmarkMode(Mode.SampleTime)
111+
@OutputTimeUnit(TimeUnit.NANOSECONDS)
112+
public int appendArrayStringBuilder(final ThreadState state) {
113+
StringBuilder buffer = state.buffer;
114+
buffer.setLength(0);
115+
ParameterFormatter.appendArray(INT_ARRAY, buffer);
116+
return state.buffer.length();
117+
}
84118
}

‎src/changelog/.2.x.x/3645_speedup_array_logging.xml

+10
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
<?xml version="1.0" encoding="UTF-8"?>
2+
<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
3+
xmlns="https://logging.apache.org/xml/ns"
4+
xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"
5+
type="fixed">
6+
<issue id="3645" link="https://github.com/apache/logging-log4j2/pull/3645"/>
7+
<description format="asciidoc">
8+
Improve performance and avoid memory consumption if logging primitive arrays as parameters
9+
</description>
10+
</entry>

0 commit comments

Comments
 (0)