Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-1096

Performance improvement for PatternMessage.format

    Details

    • Type: Improvement
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.3
    • Fix Version/s: 2.4
    • Component/s: API, Layouts
    • Labels:
      None

      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

          Issue Links

            Activity

              People

              • Assignee:
                remkop@yahoo.com Remko Popma
                Reporter:
                remkop@yahoo.com Remko Popma
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: