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.
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...)
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
Code (sorry, I will move this into a benchmark in git when I get home):
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; }
Attachments
Attachments
Issue Links
- is depended upon by
-
LOG4J2-930 Improve PatternLayout performance
-
- Closed
-