[ https://issues.apache.org/jira/browse/LOG4J2-1096?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Remko Popma resolved LOG4J2-1096. --------------------------------- Resolution: Fixed Fixed in git master in commit 8124d9b0. Added JUnit tests, and updated ParameterizedMessageBenchmark: * moved the old ParameterizedMessage::format code to ParameterizedMessageBenchmark::format * call the new ParameterizedMessage::format code from ParameterizedMessageBenchmark::formatStringArgs Final benchmark results: {noformat} On Windows 10, dual 2-core Intel(R) Core(TM) i5-3317U CPU @ 1.70GHz with Hotspot 1.8.0_51 (64 bit) Benchmark Mode Samples Score Error Units o.a.l.l.p.j.ParameterizedMessageBenchmark.format sample 163902 543.940 ± 10.994 ns/op o.a.l.l.p.j.ParameterizedMessageBenchmark.format0 sample 125285 379.937 ± 4.675 ns/op o.a.l.l.p.j.ParameterizedMessageBenchmark.format0_inlined2 sample 181395 262.358 ± 10.641 ns/op o.a.l.l.p.j.ParameterizedMessageBenchmark.formatStringArgs sample 177920 270.618 ± 10.454 ns/op {noformat} > 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 > > Attachments: sync_log_jvisualvm_profiler.png > > > 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}}. > !sync_log_jvisualvm_profiler.png! > 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-unsubscr...@logging.apache.org For additional commands, e-mail: log4j-dev-h...@logging.apache.org