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

Make use of ThreadContext.putAll on SLF4j MDCAdapter

    XMLWordPrintableJSON

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 3.0.0, 2.14.0
    • Fix Version/s: 2.14.1
    • Component/s: SLF4J Bridge
    • Labels:
      None

      Description

      Hi all.

      I maintain a service that makes use of log4j2 with the SLF4j API, and, while load testing it, I noticed some GC pressure. Taking a closer look I could understand that one of the most allocated objects were maps (and their corresponding EntrySets and Entry), coming from the MDC implementation.

      We make extensive use of Kotlin and the coroutines mechanism that the language provides. What happens is that a coroutine can suspend its execution to wait for a result, freeing the underlying thread to another coroutine. If we want to keep a MDC context that is coroutine-local (instead of thread local), the coroutines implementation callĀ MDC.setContextMap and MDC.getContextMap on each suspension (and wake). So, in pseudo-code example:

      suspend onHandleRequest(request) {
            MDC.setContextMap(<initial context>)
            dbResponseAsync = async { callDatabase() }
            service1ResponseAsync = async { callService1() }
      
            dbResponse = dbResponseAsync.await()
            service1Response  = service1ResponseAsync.await()
           
            (do something with both responses and log something here)
      }
      

      The coroutine that executes onHandleRequest will suspend (and awake) two times in the await() function. This will call MDC.setContextMap three times for the same request: 1 time at the beginning, 1 time for each await().

      I noticed that in the Log4jMDCAdapter implementation, ThreadContext.put is called for each entry of the map, creating N unmodifiable copies of the context map for each entry.

      I think it's possible to just call ThreadContext.putAll, which internally creates only a single copy for all entries. Something like:

      // Some comments here
          @Override
          @SuppressWarnings("unchecked") // nothing we can do about this, restricted by SLF4J API
          public void setContextMap(@SuppressWarnings("rawtypes") final Map map) {
              ThreadContext.clearMap();
              ThreadContext.putAll((Map<String, String>) map);
          }
      

      In our use case this greatly reduces memory footprint and GC pressure, and reduces the time to call MDC.setContextMap to roughly half.

      What do you think? Do you see any drawback?

      Happy to create a PR for this in case you agree with this change.
      Thank you.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              diogopmonteiro Diogo Monteiro
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: