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/20 15:45:45 UTC
[jira] [Resolved] (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 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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org