You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2015/08/19 17:42:46 UTC
[jira] [Updated] (LOG4J2-1096) Performance improvement for
PatternMessage.format
[ https://issues.apache.org/jira/browse/LOG4J2-1096?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Remko Popma updated LOG4J2-1096:
--------------------------------
Description:
Doing some profiling for log4j2 synchronous logging I found that the PatternConverters are hot methods. Improving these should have large impact on logging performance.
At the top of the list was {{ParameterizedMessage.format}}. (screenshot to follow)
I experimented a little and got a nice improvement by using a char[] array instead of a StringBuilder in this method. Explanation of the below benchmark results:
* format = current master: StringBuilder based code
* format0 = use char[] array instead of StringBuilder
* format0_inline = format0 + refactor to call small methods
* format0_inline2 = format0_inline + avoid index check inside loop
* format0_inline3 = refactored format0_inline2 to make all methods 35 byte codes or less (not very readable any more...)
{noformat}
Windows:
Benchmark Mode Samples Score Error Units
o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 122654 27.628 ± 0.894 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 130088 364.905 ± 20.410 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 121087 188.281 ± 1.772 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 123966 195.806 ± 23.696 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 128577 186.900 ± 1.724 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 124877 190.462 ± 2.061 ns/op
Linux
Benchmark Mode Samples Score Error Units
o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 2934379 30.959 ± 0.035 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 2630377 361.414 ± 1.960 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 2030686 240.816 ± 2.143 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 2296404 221.649 ± 4.264 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 2113582 234.008 ± 1.939 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 3618971 270.600 ± 3.689 ns/op
{noformat}
Code (sorry, I will move this into a benchmark in git when I get home):
{code}
public static String format0_inlined2(final String messagePattern,
final String[] arguments) {
int len = 0;
if (messagePattern == null || (len = messagePattern.length()) == 0
|| arguments == null || arguments.length == 0) {
return messagePattern;
}
return format0_inlined22(messagePattern, len, arguments);
}
private static String format0_inlined22(final String messagePattern,
final int len, final String[] arguments) {
final char[] result = new char[len + totalLength(arguments)];
int pos = 0;
int escapeCounter = 0;
int currentArgument = 0;
int i = 0;
for (; i < len - 1; i++) {
final char curChar = messagePattern.charAt(i);
if (curChar == ESCAPE_CHAR) {
escapeCounter++;
} else {
if (isDelimPair(messagePattern, i, curChar)) {
i++;
// write escaped escape chars
pos = format0_writeEscapedEscapeChars(escapeCounter,
result, pos);
if (isEscapeCounterOdd(escapeCounter)) {
// i.e. escaped
// write escaped escape chars
pos = format0_writeDelimPair(result, pos);
} else {
// unescaped
pos = format0_appendArg(arguments, currentArgument,
result, pos);
currentArgument++;
}
} else {
pos = format0_handleLiteralChar(result, pos, escapeCounter,
curChar);
}
escapeCounter = 0;
}
}
pos = format0_handleMaybeLastChar(messagePattern, len, result, pos,
escapeCounter, i);
return new String(result, 0, pos);
}
// 27 bytes
private static int totalLength(String[] arguments) {
int result = 0;
for (int i = 0; i < arguments.length; i++) {
result += arguments[i].length();
}
return result;
}
// 22 bytes
private static boolean isDelimPair(final String messagePattern, int i,
final char curChar) {
return curChar == DELIM_START
&& messagePattern.charAt(i + 1) == DELIM_STOP;
}
private static int format0_handleMaybeLastChar(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 = format0_handleLastChar(result, pos, escapeCounter, curChar);
}
return pos;
}
private static int format0_handleLastChar(final char[] result, int pos,
int escapeCounter, final char curChar) {
if (curChar == ESCAPE_CHAR) {
pos = format0_writeUnescapedEscapeChars(escapeCounter + 1, result,
pos);
} else {
pos = format0_handleLiteralChar(result, pos, escapeCounter, curChar);
}
return pos;
}
private static int format0_handleLiteralChar(final char[] result, int pos,
int escapeCounter, final char curChar) {
// any other char beside ESCAPE or DELIM_START/STOP-combo
// write unescaped escape chars
pos = format0_writeUnescapedEscapeChars(escapeCounter, result, pos);
result[pos++] = curChar;
return pos;
}
private static int format0_writeDelimPair(final char[] result, int pos) {
result[pos++] = DELIM_START;
result[pos++] = DELIM_STOP;
return pos;
}
private static boolean isEscapeCounterOdd(int escapeCounter) {
return (escapeCounter & 1) == 1;
}
private static int format0_writeEscapedEscapeChars(int escapeCounter,
char[] result, int pos) {
final int escapedEscapes = escapeCounter >> 1; // divide by two
return format0_writeUnescapedEscapeChars(escapedEscapes, result, pos);
}
private static int format0_writeUnescapedEscapeChars(int escapeCounter,
char[] result, int pos) {
while (escapeCounter > 0) {
result[pos++] = ESCAPE_CHAR;
escapeCounter--;
}
return pos;
}
private static int format0_appendArg(final String[] arguments,
int currentArgument, final char[] result, int pos) {
if (currentArgument < arguments.length) {
pos = format0_appendArg0(arguments, currentArgument, result, pos);
} else {
pos = format0_writeDelimPair(result, pos);
}
return pos;
}
private static int format0_appendArg0(final String[] arguments,
int currentArgument, final char[] result, int pos) {
final String arg = arguments[currentArgument];
final int argLen = arg.length();
arg.getChars(0, argLen, result, pos);
return pos + argLen;
}
{code}
was:
Doing some profiling for log4j2 synchronous logging I found that the PatternConverters are hot methods. Improving these should have large impact on logging performance.
At the top of the list was {{ParameterizedMessage.format}}. (screenshot to follow)
I experimented a little and got a nice improvement by using a char[] array instead of a StringBuilder in this method. Explanation of the below benchmark results:
* format0 = use char[] array instead of StringBuilder
* format0_inline = format0 + refactor to call small methods
* format0_inline2 = format0_inline + avoid index check inside loop
* format0_inline3 = refactored format0_inline2 to make all methods 35 byte codes or less (not very readable any more...)
{noformat}
Windows:
Benchmark Mode Samples Score Error Units
o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 122654 27.628 ± 0.894 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 130088 364.905 ± 20.410 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 121087 188.281 ± 1.772 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 123966 195.806 ± 23.696 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 128577 186.900 ± 1.724 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 124877 190.462 ± 2.061 ns/op
Linux
Benchmark Mode Samples Score Error Units
o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 2934379 30.959 ± 0.035 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 2630377 361.414 ± 1.960 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 2030686 240.816 ± 2.143 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 2296404 221.649 ± 4.264 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 2113582 234.008 ± 1.939 ns/op
o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 3618971 270.600 ± 3.689 ns/op
{noformat}
Code (sorry, I will move this into a benchmark in git when I get home):
{code}
public static String format0_inlined2(final String messagePattern,
final String[] arguments) {
int len = 0;
if (messagePattern == null || (len = messagePattern.length()) == 0
|| arguments == null || arguments.length == 0) {
return messagePattern;
}
return format0_inlined22(messagePattern, len, arguments);
}
private static String format0_inlined22(final String messagePattern,
final int len, final String[] arguments) {
final char[] result = new char[len + totalLength(arguments)];
int pos = 0;
int escapeCounter = 0;
int currentArgument = 0;
int i = 0;
for (; i < len - 1; i++) {
final char curChar = messagePattern.charAt(i);
if (curChar == ESCAPE_CHAR) {
escapeCounter++;
} else {
if (isDelimPair(messagePattern, i, curChar)) {
i++;
// write escaped escape chars
pos = format0_writeEscapedEscapeChars(escapeCounter,
result, pos);
if (isEscapeCounterOdd(escapeCounter)) {
// i.e. escaped
// write escaped escape chars
pos = format0_writeDelimPair(result, pos);
} else {
// unescaped
pos = format0_appendArg(arguments, currentArgument,
result, pos);
currentArgument++;
}
} else {
pos = format0_handleLiteralChar(result, pos, escapeCounter,
curChar);
}
escapeCounter = 0;
}
}
pos = format0_handleMaybeLastChar(messagePattern, len, result, pos,
escapeCounter, i);
return new String(result, 0, pos);
}
// 27 bytes
private static int totalLength(String[] arguments) {
int result = 0;
for (int i = 0; i < arguments.length; i++) {
result += arguments[i].length();
}
return result;
}
// 22 bytes
private static boolean isDelimPair(final String messagePattern, int i,
final char curChar) {
return curChar == DELIM_START
&& messagePattern.charAt(i + 1) == DELIM_STOP;
}
private static int format0_handleMaybeLastChar(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 = format0_handleLastChar(result, pos, escapeCounter, curChar);
}
return pos;
}
private static int format0_handleLastChar(final char[] result, int pos,
int escapeCounter, final char curChar) {
if (curChar == ESCAPE_CHAR) {
pos = format0_writeUnescapedEscapeChars(escapeCounter + 1, result,
pos);
} else {
pos = format0_handleLiteralChar(result, pos, escapeCounter, curChar);
}
return pos;
}
private static int format0_handleLiteralChar(final char[] result, int pos,
int escapeCounter, final char curChar) {
// any other char beside ESCAPE or DELIM_START/STOP-combo
// write unescaped escape chars
pos = format0_writeUnescapedEscapeChars(escapeCounter, result, pos);
result[pos++] = curChar;
return pos;
}
private static int format0_writeDelimPair(final char[] result, int pos) {
result[pos++] = DELIM_START;
result[pos++] = DELIM_STOP;
return pos;
}
private static boolean isEscapeCounterOdd(int escapeCounter) {
return (escapeCounter & 1) == 1;
}
private static int format0_writeEscapedEscapeChars(int escapeCounter,
char[] result, int pos) {
final int escapedEscapes = escapeCounter >> 1; // divide by two
return format0_writeUnescapedEscapeChars(escapedEscapes, result, pos);
}
private static int format0_writeUnescapedEscapeChars(int escapeCounter,
char[] result, int pos) {
while (escapeCounter > 0) {
result[pos++] = ESCAPE_CHAR;
escapeCounter--;
}
return pos;
}
private static int format0_appendArg(final String[] arguments,
int currentArgument, final char[] result, int pos) {
if (currentArgument < arguments.length) {
pos = format0_appendArg0(arguments, currentArgument, result, pos);
} else {
pos = format0_writeDelimPair(result, pos);
}
return pos;
}
private static int format0_appendArg0(final String[] arguments,
int currentArgument, final char[] result, int pos) {
final String arg = arguments[currentArgument];
final int argLen = arg.length();
arg.getChars(0, argLen, result, pos);
return pos + argLen;
}
{code}
> Performance improvement for PatternMessage.format
> -------------------------------------------------
>
> Key: LOG4J2-1096
> URL: https://issues.apache.org/jira/browse/LOG4J2-1096
> Project: Log4j 2
> Issue Type: Improvement
> Components: API, Layouts
> Affects Versions: 2.3
> Reporter: Remko Popma
> Assignee: Remko Popma
> Fix For: 2.4
>
>
> Doing some profiling for log4j2 synchronous logging I found that the PatternConverters are hot methods. Improving these should have large impact on logging performance.
> At the top of the list was {{ParameterizedMessage.format}}. (screenshot to follow)
> I experimented a little and got a nice improvement by using a char[] array instead of a StringBuilder in this method. Explanation of the below benchmark results:
> * format = current master: StringBuilder based code
> * format0 = use char[] array instead of StringBuilder
> * format0_inline = format0 + refactor to call small methods
> * format0_inline2 = format0_inline + avoid index check inside loop
> * format0_inline3 = refactored format0_inline2 to make all methods 35 byte codes or less (not very readable any more...)
> {noformat}
> Windows:
> Benchmark Mode Samples Score Error Units
> o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 122654 27.628 ± 0.894 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 130088 364.905 ± 20.410 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 121087 188.281 ± 1.772 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 123966 195.806 ± 23.696 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 128577 186.900 ± 1.724 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 124877 190.462 ± 2.061 ns/op
> Linux
> Benchmark Mode Samples Score Error Units
> o.a.l.l.p.j.ParameterizedMessageBenchmark.baseline sample 2934379 30.959 ± 0.035 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 2630377 361.414 ± 1.960 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 2030686 240.816 ± 2.143 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline sample 2296404 221.649 ± 4.264 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline2 sample 2113582 234.008 ± 1.939 ns/op
> o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inline3 sample 3618971 270.600 ± 3.689 ns/op
> {noformat}
> Code (sorry, I will move this into a benchmark in git when I get home):
> {code}
> public static String format0_inlined2(final String messagePattern,
> final String[] arguments) {
> int len = 0;
> if (messagePattern == null || (len = messagePattern.length()) == 0
> || arguments == null || arguments.length == 0) {
> return messagePattern;
> }
> return format0_inlined22(messagePattern, len, arguments);
> }
> private static String format0_inlined22(final String messagePattern,
> final int len, final String[] arguments) {
> final char[] result = new char[len + totalLength(arguments)];
> int pos = 0;
> int escapeCounter = 0;
> int currentArgument = 0;
> int i = 0;
> for (; i < len - 1; i++) {
> final char curChar = messagePattern.charAt(i);
> if (curChar == ESCAPE_CHAR) {
> escapeCounter++;
> } else {
> if (isDelimPair(messagePattern, i, curChar)) {
> i++;
> // write escaped escape chars
> pos = format0_writeEscapedEscapeChars(escapeCounter,
> result, pos);
> if (isEscapeCounterOdd(escapeCounter)) {
> // i.e. escaped
> // write escaped escape chars
> pos = format0_writeDelimPair(result, pos);
> } else {
> // unescaped
> pos = format0_appendArg(arguments, currentArgument,
> result, pos);
> currentArgument++;
> }
> } else {
> pos = format0_handleLiteralChar(result, pos, escapeCounter,
> curChar);
> }
> escapeCounter = 0;
> }
> }
> pos = format0_handleMaybeLastChar(messagePattern, len, result, pos,
> escapeCounter, i);
> return new String(result, 0, pos);
> }
> // 27 bytes
> private static int totalLength(String[] arguments) {
> int result = 0;
> for (int i = 0; i < arguments.length; i++) {
> result += arguments[i].length();
> }
> return result;
> }
> // 22 bytes
> private static boolean isDelimPair(final String messagePattern, int i,
> final char curChar) {
> return curChar == DELIM_START
> && messagePattern.charAt(i + 1) == DELIM_STOP;
> }
> private static int format0_handleMaybeLastChar(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 = format0_handleLastChar(result, pos, escapeCounter, curChar);
> }
> return pos;
> }
> private static int format0_handleLastChar(final char[] result, int pos,
> int escapeCounter, final char curChar) {
> if (curChar == ESCAPE_CHAR) {
> pos = format0_writeUnescapedEscapeChars(escapeCounter + 1, result,
> pos);
> } else {
> pos = format0_handleLiteralChar(result, pos, escapeCounter, curChar);
> }
> return pos;
> }
> private static int format0_handleLiteralChar(final char[] result, int pos,
> int escapeCounter, final char curChar) {
> // any other char beside ESCAPE or DELIM_START/STOP-combo
> // write unescaped escape chars
> pos = format0_writeUnescapedEscapeChars(escapeCounter, result, pos);
> result[pos++] = curChar;
> return pos;
> }
> private static int format0_writeDelimPair(final char[] result, int pos) {
> result[pos++] = DELIM_START;
> result[pos++] = DELIM_STOP;
> return pos;
> }
> private static boolean isEscapeCounterOdd(int escapeCounter) {
> return (escapeCounter & 1) == 1;
> }
> private static int format0_writeEscapedEscapeChars(int escapeCounter,
> char[] result, int pos) {
> final int escapedEscapes = escapeCounter >> 1; // divide by two
> return format0_writeUnescapedEscapeChars(escapedEscapes, result, pos);
> }
> private static int format0_writeUnescapedEscapeChars(int escapeCounter,
> char[] result, int pos) {
> while (escapeCounter > 0) {
> result[pos++] = ESCAPE_CHAR;
> escapeCounter--;
> }
> return pos;
> }
> private static int format0_appendArg(final String[] arguments,
> int currentArgument, final char[] result, int pos) {
> if (currentArgument < arguments.length) {
> pos = format0_appendArg0(arguments, currentArgument, result, pos);
> } else {
> pos = format0_writeDelimPair(result, pos);
> }
> return pos;
> }
> private static int format0_appendArg0(final String[] arguments,
> int currentArgument, final char[] result, int pos) {
> final String arg = arguments[currentArgument];
> final int argLen = arg.length();
> arg.getChars(0, argLen, result, pos);
> return pos + argLen;
> }
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org