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 18:17:45 UTC
[jira] [Comment Edited] (LOG4J2-1096) Performance improvement for
PatternMessage.format
[ https://issues.apache.org/jira/browse/LOG4J2-1096?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14703259#comment-14703259 ]
Remko Popma edited comment on LOG4J2-1096 at 8/19/15 4:16 PM:
--------------------------------------------------------------
How to read the results:
The current StringBuilder-based code ({{format}} in the benchmark) takes 360ns. The proposed char[]-based improvements ({{format0...}} in the benchmark) give between 30% (240ns on linux) to 50% (188ns on Windows) better performance.
The difference between the various format0 variations is relatively minor.
Please disregard {{format0_inline3}}. It was an experiment; I did not like the resulting code and the performance was not great. This leaves the {{format0}}, {{format0_inline}} and {{format0_inline2}} variations.
The {{format0}} variation (simply replacing StringBuilder with char[]) gives a nice improvement. This alone is worth doing.
Can we do better? Refactoring some logic to separate smaller methods (the {{format0_inline}} variation) seems to make things slightly worse on Windows and better on Linux, but the {{format0_inline2}} variation seems better than {{format0}} on both platforms. The code above is for the {{format0_inline2}} variation. The difference with format0_inline is fairly minor: instead of looping between {{i=0;i<len}}, format0_inline2 loops between {{i=0;i<len-1}} and has some code to deal with the last element after the loop. This seems to give consistent results with little variation on both platforms.
My conclusion is that {{format0}} and {{format0_inline2}} are similar in performance but both are a lot faster than the current StringBuilder based code.
was (Author: remkop@yahoo.com):
How to read the results:
The current StringBuilder-based code ({{format}} in the benchmark) takes 360ns. The proposed char[]-based improvements ({{format0...}} in the benchmark) give between 30% (240ns on linux) to 50% (188ns on Windows) better performance.
The difference between the various format0 variations is relatively minor.
Please disregard {{format0_inline3}}. It was an experiment; I did not like the resulting code and the performance was not great. This leaves the {{format0}}, {{format0_inline}} and {{format0_inline2}} variations.
The {{format0}} variation (simply replacing StringBuilder with char[]) gives a nice improvement. This alone is worth doing.
Can we do better? Refactoring some logic to separate smaller methods (the {{format0_inline}} variation) seems to make things slightly worse on Windows and better on Linux, but the {{format0_inline2}} variation seems better than {{format0}} on both platforms. The code above is for the {{format0_inline2}} variation. The difference with format0 is fairly minor: instead of looping between {{i=0;i<len}}, format0_inline2 loops between {{i=0;i<len-1}} and has some code to deal with the last element after the loop. This seems to give consistent results with little variation on both platforms.
My conclusion is that {{format0}} and {{format0_inline2}} are similar in performance but both are a lot faster than the current StringBuilder based 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