[LOG4J2-2990] Make use of ThreadContext.putAll on SLF4j MDCAdapter

• 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
• Assignee: Unassigned
• Reporter: Diogo Monteiro
• Created: 05/Jan/21 18:29
• Updated: 08/Feb/21 09:43
• Resolved: 07/Feb/21 21:59

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.