You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rp...@apache.org on 2015/08/20 15:38:08 UTC
logging-log4j2 git commit: LOG4J2-1096 improved
ParameterizedMessage::getFormattedMessage performance by ~2X by replacing
StringBuilder by a char[] array and factoring out code to small methods that
are easy for the JVM to inline
Repository: logging-log4j2
Updated Branches:
refs/heads/master d4d80ad5c -> 8124d9b0d
LOG4J2-1096 improved ParameterizedMessage::getFormattedMessage
performance by ~2X by replacing StringBuilder by a char[] array and
factoring out code to small methods that are easy for the JVM to inline
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/8124d9b0
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/8124d9b0
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/8124d9b0
Branch: refs/heads/master
Commit: 8124d9b0db636291ee7b23a59d293e31c56a63a8
Parents: d4d80ad
Author: rpopma <rp...@apache.org>
Authored: Thu Aug 20 22:38:13 2015 +0900
Committer: rpopma <rp...@apache.org>
Committed: Thu Aug 20 22:38:13 2015 +0900
----------------------------------------------------------------------
.../log4j/message/ParameterizedMessage.java | 208 ++++++++++++++++---
.../log4j/message/ParameterizedMessageTest.java | 48 +++++
.../perf/jmh/ParameterizedMessageBenchmark.java | 61 +++++-
src/changes/changes.xml | 3 +
4 files changed, 289 insertions(+), 31 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/8124d9b0/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java
----------------------------------------------------------------------
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 6b71eff..1a9175b 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
@@ -210,7 +210,7 @@ public class ParameterizedMessage implements Message {
}
protected String formatMessage(final String msgPattern, final String[] sArgs) {
- return format(msgPattern, sArgs);
+ return formatStringArgs(msgPattern, sArgs);
}
@Override
@@ -253,53 +253,201 @@ public class ParameterizedMessage implements Message {
if (messagePattern == null || arguments == null || arguments.length == 0) {
return messagePattern;
}
+ if (arguments instanceof String[]) {
+ return formatStringArgs(messagePattern, (String[]) arguments);
+ }
+ final String[] stringArgs = new String[arguments.length];
+ for (int i = 0; i < arguments.length; i++) {
+ stringArgs[i] = String.valueOf(arguments[i]);
+ }
+ return formatStringArgs(messagePattern, stringArgs);
+ }
+
+ /**
+ * Replace placeholders in the given messagePattern with arguments.
+ * <p>
+ * Package protected for unit tests.
+ *
+ * @param messagePattern the message pattern containing placeholders.
+ * @param arguments the arguments to be used to replace placeholders.
+ * @return the formatted message.
+ */
+ // 33 bytes
+ static String formatStringArgs(final String messagePattern, final String[] arguments) {
+ int len = 0;
+ if (messagePattern == null || (len = messagePattern.length()) == 0 || arguments == null
+ || arguments.length == 0) {
+ return messagePattern;
+ }
+
+ return formatStringArgs0(messagePattern, len, arguments);
+ }
- final StringBuilder result = new StringBuilder();
+ // 157 bytes
+ private static String formatStringArgs0(final String messagePattern, final int len, final String[] arguments) {
+ final char[] result = new char[len + sumStringLengths(arguments)];
+ int pos = 0;
int escapeCounter = 0;
int currentArgument = 0;
- for (int i = 0; i < messagePattern.length(); i++) {
+ int i = 0;
+ for (; i < len - 1; i++) { // last char is excluded from the loop
final char curChar = messagePattern.charAt(i);
if (curChar == ESCAPE_CHAR) {
escapeCounter++;
} else {
- if (curChar == DELIM_START && i < messagePattern.length() - 1
- && messagePattern.charAt(i + 1) == DELIM_STOP) {
+ if (isDelimPair(curChar, messagePattern, i)) { // looks ahead one char
+ i++;
+
// write escaped escape chars
- final int escapedEscapes = escapeCounter / 2;
- for (int j = 0; j < escapedEscapes; j++) {
- result.append(ESCAPE_CHAR);
- }
+ pos = writeEscapedEscapeChars(escapeCounter, result, pos);
- if (escapeCounter % 2 == 1) {
+ if (isOdd(escapeCounter)) {
// i.e. escaped
// write escaped escape chars
- result.append(DELIM_START);
- result.append(DELIM_STOP);
+ pos = writeDelimPair(result, pos);
} else {
// unescaped
- if (currentArgument < arguments.length) {
- result.append(arguments[currentArgument]);
- } else {
- result.append(DELIM_START).append(DELIM_STOP);
- }
+ pos = writeArgOrDelimPair(arguments, currentArgument, result, pos);
currentArgument++;
}
- i++;
- escapeCounter = 0;
- continue;
- }
- // any other char beside ESCAPE or DELIM_START/STOP-combo
- // write unescaped escape chars
- if (escapeCounter > 0) {
- for (int j = 0; j < escapeCounter; j++) {
- result.append(ESCAPE_CHAR);
- }
- escapeCounter = 0;
+ } else {
+ pos = handleLiteralChar(result, pos, escapeCounter, curChar);
}
- result.append(curChar);
+ escapeCounter = 0;
}
}
- return result.toString();
+ pos = handleRemainingCharIfAny(messagePattern, len, result, pos, escapeCounter, i);
+ return new String(result, 0, pos);
+ }
+
+ /**
+ * Returns the sum of the lengths of all Strings in the specified array.
+ */
+ // 27 bytes
+ private static int sumStringLengths(final String[] arguments) {
+ int result = 0;
+ for (int i = 0; i < arguments.length; i++) {
+ result += arguments[i].length();
+ }
+ return result;
+ }
+
+ /**
+ * Returns {@code true} if the specified char and the char at {@code curCharIndex + 1} in the specified message
+ * pattern together form a "{}" delimiter pair, returns {@code false} otherwise.
+ */
+ // 22 bytes
+ private static boolean isDelimPair(final char curChar, final String messagePattern, final int curCharIndex) {
+ return curChar == DELIM_START && messagePattern.charAt(curCharIndex + 1) == DELIM_STOP;
+ }
+
+ /**
+ * Detects whether the message pattern has been fully processed or if an unprocessed character remains and processes
+ * it if necessary, returning the resulting position in the result char array.
+ */
+ // 28 bytes
+ private static int handleRemainingCharIfAny(final String messagePattern, final int len, final char[] result,
+ int pos, int escapeCounter, int i) {
+ if (i == len - 1) {
+ final char curChar = messagePattern.charAt(i);
+ pos = handleLastChar(result, pos, escapeCounter, curChar);
+ }
+ return pos;
+ }
+
+ /**
+ * Processes the last unprocessed character and returns the resulting position in the result char array.
+ */
+ // 28 bytes
+ private static int handleLastChar(final char[] result, int pos, final int escapeCounter, final char curChar) {
+ if (curChar == ESCAPE_CHAR) {
+ pos = writeUnescapedEscapeChars(escapeCounter + 1, result, pos);
+ } else {
+ pos = handleLiteralChar(result, pos, escapeCounter, curChar);
+ }
+ return pos;
+ }
+
+ /**
+ * Processes a literal char (neither an '\' escape char nor a "{}" delimiter pair) and returns the resulting
+ * position.
+ */
+ // 16 bytes
+ private static int handleLiteralChar(final char[] result, int pos, final int escapeCounter, final char curChar) {
+ // any other char beside ESCAPE or DELIM_START/STOP-combo
+ // write unescaped escape chars
+ pos = writeUnescapedEscapeChars(escapeCounter, result, pos);
+ result[pos++] = curChar;
+ return pos;
+ }
+
+ /**
+ * Writes "{}" to the specified result array at the specified position and returns the resulting position.
+ */
+ // 18 bytes
+ private static int writeDelimPair(final char[] result, int pos) {
+ result[pos++] = DELIM_START;
+ result[pos++] = DELIM_STOP;
+ return pos;
+ }
+
+ /**
+ * Returns {@code true} if the specified parameter is odd.
+ */
+ // 11 bytes
+ private static boolean isOdd(final int number) {
+ return (number & 1) == 1;
+ }
+
+ /**
+ * Writes a '\' char to the specified result array (starting at the specified position) for each <em>pair</em> of
+ * '\' escape chars encountered in the message format and returns the resulting position.
+ */
+ // 11 bytes
+ private static int writeEscapedEscapeChars(final int escapeCounter, final char[] result, final int pos) {
+ final int escapedEscapes = escapeCounter >> 1; // divide by two
+ return writeUnescapedEscapeChars(escapedEscapes, result, pos);
+ }
+
+ /**
+ * Writes the specified number of '\' chars to the specified result array (starting at the specified position) and
+ * returns the resulting position.
+ */
+ // 20 bytes
+ private static int writeUnescapedEscapeChars(int escapeCounter, char[] result, int pos) {
+ while (escapeCounter > 0) {
+ result[pos++] = ESCAPE_CHAR;
+ escapeCounter--;
+ }
+ return pos;
+ }
+
+ /**
+ * Appends the argument at the specified argument index (or, if no such argument exists, the "{}" delimiter pair) to
+ * the specified result char array at the specified position and returns the resulting position.
+ */
+ // 25 bytes
+ private static int writeArgOrDelimPair(final String[] arguments, final int currentArgument, final char[] result,
+ int pos) {
+ if (currentArgument < arguments.length) {
+ pos = writeArgAt0(arguments, currentArgument, result, pos);
+ } else {
+ pos = writeDelimPair(result, pos);
+ }
+ return pos;
+ }
+
+ /**
+ * Appends the argument at the specified argument index to the specified result char array at the specified position
+ * and returns the resulting position.
+ */
+ // 27 bytes
+ private static int writeArgAt0(final String[] arguments, final int currentArgument, final char[] result,
+ final int pos) {
+ final String arg = arguments[currentArgument];
+ final int argLen = arg.length();
+ arg.getChars(0, argLen, result, pos);
+ return pos + argLen;
}
/**
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/8124d9b0/log4j-api/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageTest.java
----------------------------------------------------------------------
diff --git a/log4j-api/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageTest.java b/log4j-api/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageTest.java
index 1ffc9cb..5ca48df 100644
--- a/log4j-api/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageTest.java
+++ b/log4j-api/src/test/java/org/apache/logging/log4j/message/ParameterizedMessageTest.java
@@ -38,6 +38,54 @@ public class ParameterizedMessageTest {
}
@Test
+ public void testFormat3StringArgs() {
+ final String testMsg = "Test message {}{} {}";
+ final String[] args = { "a", "b", "c" };
+ final String result = ParameterizedMessage.formatStringArgs(testMsg, args);
+ assertEquals("Test message ab c", result);
+ }
+
+ @Test
+ public void testFormatStringArgsIgnoresSuperfluousArgs() {
+ final String testMsg = "Test message {}{} {}";
+ final String[] args = { "a", "b", "c", "unnecessary", "superfluous" };
+ final String result = ParameterizedMessage.formatStringArgs(testMsg, args);
+ assertEquals("Test message ab c", result);
+ }
+
+ @Test
+ public void testFormatStringArgsWithEscape() {
+ final String testMsg = "Test message \\{}{} {}";
+ final String[] args = { "a", "b", "c" };
+ final String result = ParameterizedMessage.formatStringArgs(testMsg, args);
+ assertEquals("Test message {}a b", result);
+ }
+
+ @Test
+ public void testFormatStringArgsWithTrailingEscape() {
+ final String testMsg = "Test message {}{} {}\\";
+ final String[] args = { "a", "b", "c" };
+ final String result = ParameterizedMessage.formatStringArgs(testMsg, args);
+ assertEquals("Test message ab c\\", result);
+ }
+
+ @Test
+ public void testFormatStringArgsWithTrailingEscapedEscape() {
+ final String testMsg = "Test message {}{} {}\\\\";
+ final String[] args = { "a", "b", "c" };
+ final String result = ParameterizedMessage.formatStringArgs(testMsg, args);
+ assertEquals("Test message ab c\\\\", result);
+ }
+
+ @Test
+ public void testFormatStringArgsWithEscapedEscape() {
+ final String testMsg = "Test message \\\\{}{} {}";
+ final String[] args = { "a", "b", "c" };
+ final String result = ParameterizedMessage.formatStringArgs(testMsg, args);
+ assertEquals("Test message \\ab c", result);
+ }
+
+ @Test
public void testSafeWithMutableParams() { // LOG4J2-763
final String testMsg = "Test message {}";
final Mutable param = new Mutable().set("abc");
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/8124d9b0/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ParameterizedMessageBenchmark.java
----------------------------------------------------------------------
diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ParameterizedMessageBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ParameterizedMessageBenchmark.java
index 08494dc..728d2dc 100644
--- a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ParameterizedMessageBenchmark.java
+++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ParameterizedMessageBenchmark.java
@@ -54,7 +54,7 @@ public class ParameterizedMessageBenchmark {
@BenchmarkMode(Mode.SampleTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public String format() {
- return ParameterizedMessage.format("pattern {} with {} two parameters and some text", ARGS);
+ return format("pattern {} with {} two parameters and some text", ARGS);
}
@Benchmark
@@ -67,9 +67,68 @@ public class ParameterizedMessageBenchmark {
@Benchmark
@BenchmarkMode(Mode.SampleTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public String formatStringArgs() {
+ return ParameterizedMessage.format("pattern {} with {} two parameters and some text", ARGS);
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
public String format0_inlined2() {
return format0_inlined2("pattern {} with {} two parameters and some text", ARGS);
}
+ public static String format(final String messagePattern, final Object[] arguments) {
+ if (messagePattern == null || arguments == null || arguments.length == 0) {
+ return messagePattern;
+ }
+
+ final StringBuilder result = new StringBuilder();
+ int escapeCounter = 0;
+ int currentArgument = 0;
+ for (int i = 0; i < messagePattern.length(); i++) {
+ final char curChar = messagePattern.charAt(i);
+ if (curChar == ESCAPE_CHAR) {
+ escapeCounter++;
+ } else {
+ if (curChar == DELIM_START && i < messagePattern.length() - 1
+ && messagePattern.charAt(i + 1) == DELIM_STOP) {
+ // write escaped escape chars
+ final int escapedEscapes = escapeCounter / 2;
+ for (int j = 0; j < escapedEscapes; j++) {
+ result.append(ESCAPE_CHAR);
+ }
+
+ if (escapeCounter % 2 == 1) {
+ // i.e. escaped
+ // write escaped escape chars
+ result.append(DELIM_START);
+ result.append(DELIM_STOP);
+ } else {
+ // unescaped
+ if (currentArgument < arguments.length) {
+ result.append(arguments[currentArgument]);
+ } else {
+ result.append(DELIM_START).append(DELIM_STOP);
+ }
+ currentArgument++;
+ }
+ i++;
+ escapeCounter = 0;
+ continue;
+ }
+ // any other char beside ESCAPE or DELIM_START/STOP-combo
+ // write unescaped escape chars
+ if (escapeCounter > 0) {
+ for (int j = 0; j < escapeCounter; j++) {
+ result.append(ESCAPE_CHAR);
+ }
+ escapeCounter = 0;
+ }
+ result.append(curChar);
+ }
+ }
+ return result.toString();
+ }
// 259 bytes
public static String format0(final String messagePattern, final String[] arguments) {
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/8124d9b0/src/changes/changes.xml
----------------------------------------------------------------------
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index f525871..a92f0c1 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -31,6 +31,9 @@
Added support for Java 8 lambda expressions to lazily construct a log message only if
the requested log level is enabled.
</action>
+ <action issue="LOG4J2-1096" dev="rpopma" type="update">
+ Improved performance of ParameterizedMessage::getFormattedMessage by ~2X.
+ </action>
<action issue="LOG4J2-1044" dev="rgoers" type="fix">
Write pending events to Flume when the appender is stopped.
</action>