Log4j 2
  1. Log4j 2
  2. LOG4J2-154

ThreadContext performance improvement: shallow copies for reads, deep copies for writes

    Details

    • Type: Improvement Improvement
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta3
    • Fix Version/s: 2.0-beta7
    • Component/s: Core
    • Labels:
      None

      Description

      Currently, every time a Log4jLogEvent object is created, a deep copy is made of both the context map and the context stack. However, expected usage is that only a few objects are pushed onto the stack or put in the context map, while the number of LogEvents is in the thousands or millions.
      Essentially, there are far more reads than writes, so using a copy-on-write mechanism should give us better performance.

      Example context map put: deep copy (expensive but rare)
      public static void put(String key, String value) {
      if (!useMap)

      { return; }
      Map<String, String> map = localMap.get();
      Map<String, String> copy = null;
      if (map == null) { copy = new HashMap<String, String>(); } else { copy = new HashMap<String, String>(map); }
      copy.put(key, value);
      localMap.set(copy);
      }

      Example context stack push: deep copy (expensive but rare)
      public static void push(String message) {
      if (!useStack) { return; }

      ContextStack stack = localStack.get();
      ContextStack copy = null;
      if (stack == null)

      { copy = new ThreadContextStack(); }

      else

      { copy = stack.copy(); }

      copy.push(message);
      localStack.set(copy);
      }

      Now, when the Log4jLogEvents are created, they just call ThreadContext.getImmutableContext and getImmutableStack. These methods return an unmodifiable wrapper around the most recent copy.

      Example for context map:
      public static Map<String, String> getImmutableContext()

      { Map<String, String> map = localMap.get(); return map == null ? EMPTY_MAP : Collections.unmodifiableMap(map); }

      Example for context stack:
      public static ContextStack getImmutableStack()

      { ContextStack stack = localStack.get(); return stack == null ? EMPTY_STACK : new ImmutableStack(stack.asList()); }

      Note that ThreadContext.ThreadContextStack needs to be changed to contain an ArrayList rather than extend it, to facilitate making both deep mutable copies and shallow immutable copies.

      private static class ThreadContextStack implements ContextStack {

      private static final long serialVersionUID = 5050501L;

      private List<String> list;

      public ThreadContextStack()

      { list = new ArrayList<String>(); }

      /**

      • This constructor uses the specified list as its internal data
      • structure unchanged. It does not make a defensive copy.
        */
        public ThreadContextStack(List<String> aList) { list = aList; // don't copy! }

      /**

      • This constructor copies the elements of the specified collection into
      • a new list. Changes to the specified collection will not affect this
      • {@code ThreadContextStack}

        .
        */
        public ThreadContextStack(Collection<String> collection)

        { list = new ArrayList<String>(collection); }

      public void clear()

      { list.clear(); }

      public String pop() {
      int index = list.size() - 1;
      if (index >= 0)

      { String result = list.get(index); list.remove(index); return result; }

      throw new NoSuchElementException("The ThreadContext stack is empty");
      }

      public String peek() {
      int index = list.size() - 1;
      if (index >= 0)

      { return list.get(index); }

      return null;
      }

      public void push(String message)

      { list.add(message); }

      public int getDepth()

      { return list.size(); }

      public List<String> asList()

      { return list; }

      public void trim(int depth) {
      if (depth < 0)

      { throw new IllegalArgumentException( "Maximum stack depth cannot be negative"); }

      while (list.size() > depth)

      { list.remove(list.size() - 1); }

      }

      /**

      • Returns a deep copy of this stack.
        */
        public ContextStack copy() { return new ThreadContextStack(new ArrayList<>(list)); }

        }

      1. LOG4J2-154.patch
        31 kB
        Ralph Goers
      2. LOG4J2-154-patch-DefaultThreadContextMap.txt
        2 kB
        Remko Popma
      3. LOG4J2-154-patch-ThreadContext.txt
        9 kB
        Remko Popma
      4. LOG4J2-154-patch-ThreadContextMap.txt
        0.7 kB
        Remko Popma

        Issue Links

          Activity

          Hide
          Remko Popma added a comment -

          Just FYI, I'm seeing some nice performance improvements with this change.

          1 thread: 33% more throughput (2.4M ops/sec -> 3.2M ops/sec), avg. latency down 630 ns/op -> 450 ns/op
          2 threads: 62% more throughput (0.96M ops/sec -> 1.56M ops/sec), avg. latency down 787 ns/op -> 600 ns/op

          (With all loggers async on Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 dual CPU @2.93Ghz with hyperthreading switched on (16 virtual cores))

          Darn! I guess this means I have to redo all the performance testing for the http://logging.apache.org/log4j/2.x/manual/async.html#Performance page... That's a lot of work! Oh well...

          Show
          Remko Popma added a comment - Just FYI, I'm seeing some nice performance improvements with this change. 1 thread: 33% more throughput (2.4M ops/sec -> 3.2M ops/sec), avg. latency down 630 ns/op -> 450 ns/op 2 threads: 62% more throughput (0.96M ops/sec -> 1.56M ops/sec), avg. latency down 787 ns/op -> 600 ns/op (With all loggers async on Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 dual CPU @2.93Ghz with hyperthreading switched on (16 virtual cores)) Darn! I guess this means I have to redo all the performance testing for the http://logging.apache.org/log4j/2.x/manual/async.html#Performance page... That's a lot of work! Oh well...
          Hide
          Remko Popma added a comment -

          Initial fix for this issue (use copy-on-write map and stack in ThreadContext) is now committed to trunk (revision 1486482).

          This includes the method name changes mentioned in the previous comment above. Let me know if you disagree with the method name changes.

          Show
          Remko Popma added a comment - Initial fix for this issue (use copy-on-write map and stack in ThreadContext) is now committed to trunk (revision 1486482). This includes the method name changes mentioned in the previous comment above. Let me know if you disagree with the method name changes.
          Hide
          Remko Popma added a comment - - edited

          Request for feedback:
          In interface org.apache.logging.log4j.spi.ThreadContextMap,
          I would like to rename two methods, to clarify their intention and usage:

          Current:

              /**
               * Get a copy of current thread's context Map.
               * @return a copy of the context.
               */
              Map<String, String> getContext();
          
              /**
               * Return the actual context Map.
               * @return the actual context Map.
               */
              Map<String, String> get();
          

          Proposed change:

              /**
               * Get a non-{@code null} mutable copy of current thread's context Map.
               * @return a mutable copy of the context.
               */
              Map<String, String> getCopy();
          
              /**
               * Return an immutable view on the context Map or {@code null} if the context map is empty.
               * @return an immutable context Map or {@code null}.
               */
              Map<String, String> getImmutableMapOrNull();
          

          The reason I'm asking is that this is the API module, and on top of that these methods are in an SPI interface, so I thought I'd ask before making this change...

          Thoughts?

          Show
          Remko Popma added a comment - - edited Request for feedback: In interface org.apache.logging.log4j.spi.ThreadContextMap, I would like to rename two methods, to clarify their intention and usage: Current: /** * Get a copy of current thread's context Map. * @ return a copy of the context. */ Map< String , String > getContext(); /** * Return the actual context Map. * @ return the actual context Map. */ Map< String , String > get(); Proposed change: /** * Get a non-{@code null } mutable copy of current thread's context Map. * @ return a mutable copy of the context. */ Map< String , String > getCopy(); /** * Return an immutable view on the context Map or {@code null } if the context map is empty. * @ return an immutable context Map or {@code null }. */ Map< String , String > getImmutableMapOrNull(); The reason I'm asking is that this is the API module, and on top of that these methods are in an SPI interface, so I thought I'd ask before making this change... Thoughts?
          Hide
          Remko Popma added a comment -

          Ok, thanks for the confirm.

          Show
          Remko Popma added a comment - Ok, thanks for the confirm.
          Hide
          Ralph Goers added a comment -

          Normally CTR is OK. I didn't do that for this because the changes could have a wide impact and I wanted other eyes to review it. I'm pretty comfortable with the changes to the ContextMap but the ContextStack concerned me. Personally, I have no idea why anyone would want to use the ContextStack but since it was part of Log4j 1 I didn't feel I could drop it.

          Feel free to run with this.

          Show
          Ralph Goers added a comment - Normally CTR is OK. I didn't do that for this because the changes could have a wide impact and I wanted other eyes to review it. I'm pretty comfortable with the changes to the ContextMap but the ContextStack concerned me. Personally, I have no idea why anyone would want to use the ContextStack but since it was part of Log4j 1 I didn't feel I could drop it. Feel free to run with this.
          Hide
          Remko Popma added a comment - - edited

          Ralph, I would like to take the next step with this issue, but how to proceed with this? Shall I do what you did before: post a patch and ask for feedback? Or is commit-then-review ok? Either works for me.

          I was thinking to start with your patch, and start by applying the changes I mentioned in my comment above.

          Show
          Remko Popma added a comment - - edited Ralph, I would like to take the next step with this issue, but how to proceed with this? Shall I do what you did before: post a patch and ask for feedback? Or is commit-then-review ok? Either works for me. I was thinking to start with your patch, and start by applying the changes I mentioned in my comment above.
          Hide
          Remko Popma added a comment -

          Ralph, sorry for taking so long to get back. Looks good, very clean! Below are some things I noticed.

          ThreadContext: EMPTY_STACK is currently mutable
          Before:
          public static final ThreadContextStack EMPTY_STACK = new MutableThreadContextStack(new ArrayList<String>());
          After:
          public static final ThreadContextStack EMPTY_STACK = new MutableThreadContextStack(Collections.emptyList());


          DefaultThreadContextStack:
          1. avoid multiple calls to stack.get() within one method as value may have been changed/removed by another thread between calls.
          for example: "if (stack.get() != null)

          {return stack.get().size();}

          " may result in NullPointerExceptions
          2. I would use Collections.emptyList and Collections.emptyIterator to avoid creating ArrayList objects where possible

          DefaultThreadContextStack#copy()
          Before:
          if (!useStack || stack.get() == null)

          { return new MutableThreadContextStack(new ArrayList<String>()); }
          return new MutableThreadContextStack(stack.get());
          After:
          List<String> list = null;
          if (!useStack || (list = stack.get()) == null) { return new MutableThreadContextStack(new ArrayList<String>()); }

          return new MutableThreadContextStack(list);

          DefaultThreadContextStack#size()
          Before:
          return stack.get() == null ? 0 : stack.get().size();
          After:
          List<String> list = stack.get();
          return list == null ? 0 : list.size();

          DefaultThreadContextStack#isEmpty()
          Before:
          return stack.get() == null ? 0 : stack.get().isEmpty();
          After:
          List<String> list = stack.get();
          return list == null ? 0 : list.isEmpty();

          DefaultThreadContextStack#contains(Object o)
          Before:
          return stack.get() == null ? 0 : stack.get().contains(o);
          After:
          List<String> list = stack.get();
          return list == null ? 0 : list.contains(o);

          DefaultThreadContextStack#iterator()
          Before:
          if (stack.get() == null)

          { return new ArrayList<String>().iterator(); }

          else

          { return stack.get().iterator(); }

          After:
          List<String> list = stack.get();
          if (list == null)

          { return Collections.emptyIterator(); // avoid creating ArrayList }

          else

          { return list.iterator(); }

          DefaultThreadContextStack#toArray()
          Before:
          if (stack.get() == null)

          { return new String[0]; } else { List<String> list = stack.get(); return stack.get().toArray(new Object[list.size()]); }
          After:
          List<String> list = stack.get();
          if (list == null) { return new String[0]; }

          else

          { return list.toArray(new Object[list.size()]); }

          DefaultThreadContextStack#toArray(T[] ts)
          Before:
          if (stack.get() == null)

          { return new ArrayList<String>().toArray(ts); }

          return stack.get().toArray(ts);
          After:
          List<String> list = stack.get();
          if (list == null)

          { return Collections.emptyList().toArray(ts); // avoid creating new ArrayList }

          return list.toArray(ts);

          Show
          Remko Popma added a comment - Ralph, sorry for taking so long to get back. Looks good, very clean! Below are some things I noticed. ThreadContext: EMPTY_STACK is currently mutable Before: public static final ThreadContextStack EMPTY_STACK = new MutableThreadContextStack(new ArrayList<String>()); After: public static final ThreadContextStack EMPTY_STACK = new MutableThreadContextStack(Collections.emptyList()); DefaultThreadContextStack: 1. avoid multiple calls to stack.get() within one method as value may have been changed/removed by another thread between calls. for example: "if (stack.get() != null) {return stack.get().size();} " may result in NullPointerExceptions 2. I would use Collections.emptyList and Collections.emptyIterator to avoid creating ArrayList objects where possible DefaultThreadContextStack#copy() Before: if (!useStack || stack.get() == null) { return new MutableThreadContextStack(new ArrayList<String>()); } return new MutableThreadContextStack(stack.get()); After: List<String> list = null; if (!useStack || (list = stack.get()) == null) { return new MutableThreadContextStack(new ArrayList<String>()); } return new MutableThreadContextStack(list); DefaultThreadContextStack#size() Before: return stack.get() == null ? 0 : stack.get().size(); After: List<String> list = stack.get(); return list == null ? 0 : list.size(); DefaultThreadContextStack#isEmpty() Before: return stack.get() == null ? 0 : stack.get().isEmpty(); After: List<String> list = stack.get(); return list == null ? 0 : list.isEmpty(); DefaultThreadContextStack#contains(Object o) Before: return stack.get() == null ? 0 : stack.get().contains(o); After: List<String> list = stack.get(); return list == null ? 0 : list.contains(o); DefaultThreadContextStack#iterator() Before: if (stack.get() == null) { return new ArrayList<String>().iterator(); } else { return stack.get().iterator(); } After: List<String> list = stack.get(); if (list == null) { return Collections.emptyIterator(); // avoid creating ArrayList } else { return list.iterator(); } DefaultThreadContextStack#toArray() Before: if (stack.get() == null) { return new String[0]; } else { List<String> list = stack.get(); return stack.get().toArray(new Object[list.size()]); } After: List<String> list = stack.get(); if (list == null) { return new String[0]; } else { return list.toArray(new Object[list.size()]); } DefaultThreadContextStack#toArray(T[] ts) Before: if (stack.get() == null) { return new ArrayList<String>().toArray(ts); } return stack.get().toArray(ts); After: List<String> list = stack.get(); if (list == null) { return Collections.emptyList().toArray(ts); // avoid creating new ArrayList } return list.toArray(ts);
          Hide
          Ralph Goers added a comment -

          Based on what I saw from your code I have created my own version of a patch for this issue. Normally I follow the Commit-Then-Review model and have others review my commits after they are done. But in this case I would really like some feedback before I apply the patch to see if anyone can spot problems with it.

          Show
          Ralph Goers added a comment - Based on what I saw from your code I have created my own version of a patch for this issue. Normally I follow the Commit-Then-Review model and have others review my commits after they are done. But in this case I would really like some feedback before I apply the patch to see if anyone can spot problems with it.
          Hide
          Remko Popma added a comment -

          Not really, the code in the comment was for beta3, but the attached patches are for beta4 and should just work with current trunk.
          Also, the FastLog4j-v2-for-beta4.zip file attached to LOG4J2-151 contains the same files. Might save you some work. Sorry if I was unclear.

          Show
          Remko Popma added a comment - Not really, the code in the comment was for beta3, but the attached patches are for beta4 and should just work with current trunk. Also, the FastLog4j-v2-for-beta4.zip file attached to LOG4J2-151 contains the same files. Might save you some work. Sorry if I was unclear.
          Hide
          Ralph Goers added a comment -

          The patch you supplied for this in LOG4J2-151 was for beta3. ThreadContext changed a bit for beta4. I've been working on taking the concepts from your patch and refactoring the beta4 code to do what you are suggesting.

          Show
          Ralph Goers added a comment - The patch you supplied for this in LOG4J2-151 was for beta3. ThreadContext changed a bit for beta4. I've been working on taking the concepts from your patch and refactoring the beta4 code to do what you are suggesting.
          Hide
          Remko Popma added a comment -

          attached patches are based on trunk.

          Patch description:

          • ThreadContext performance improvement: copy the internal data structure for every modification, so we don't need to make a deep copy when returning an immutable Map or Stack.
          • same for DefaultThreadContextMap
          • added method getImmutableContext to ThreadContextMap: a fast implementation of this method is key to performance
          Show
          Remko Popma added a comment - attached patches are based on trunk. Patch description: ThreadContext performance improvement: copy the internal data structure for every modification, so we don't need to make a deep copy when returning an immutable Map or Stack. same for DefaultThreadContextMap added method getImmutableContext to ThreadContextMap: a fast implementation of this method is key to performance

            People

            • Assignee:
              Remko Popma
              Reporter:
              Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development