logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Gary Gregory (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-1096) Performance improvement for PatternMessage.format
Date Thu, 20 Aug 2015 00:11:46 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-1096?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14704026#comment-14704026
] 

Gary Gregory commented on LOG4J2-1096:
--------------------------------------

When I run {{mvn package -DskipTests -pl log4j-perf}} I get 100 compiler errors like:

{norformat}
[ERROR] E:\vcs\git\apache\logging\logging-log4j2\log4j-perf\target\generated-sources\annotations\org\openjdk\jmh\infra\generated\Blackhole_jmh_B1.java:[3,7]
error: duplicate class: org.openjdk.jmh.infra.generated.Blackhole_jmh_B1
[ERROR] E:\vcs\git\apache\logging\logging-log4j2\log4j-perf\target\generated-sources\annotations\org\openjdk\jmh\infra\generated\Blackhole_jmh_B2.java:[3,7]
error: duplicate class: org.openjdk.jmh.infra.generated.Blackhole_jmh_B2
[ERROR] E:\vcs\git\apache\logging\logging-log4j2\log4j-perf\target\generated-sources\annotations\org\openjdk\jmh\infra\generated\Blackhole_jmh_B3.java:[2,7]
error: duplicate class: org.openjdk.jmh.infra.generated.Blackhole_jmh_B3
[ERROR] E:\vcs\git\apache\logging\logging-log4j2\log4j-perf\target\generated-sources\annotations\org\openjdk\jmh\infra\generated\Blackhole_jmh.java:[2,7]
error: duplicate class: org.openjdk.jmh.infra.generated.Blackhole_jmh
...
{norformat}

I'd like to run these new benchmarks. Help?

> 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


Mime
View raw message