[jira] [Created] (LOG4J2-2990) Make use of ThreadContext.putAll on SLF4j MDCAdapter

["Diogo Monteiro (Jira)" <ji...@apache.org>]

Diogo Monteiro created LOG4J2-2990:
--------------------------------------

             Summary: Make use of ThreadContext.putAll on SLF4j MDCAdapter
                 Key: LOG4J2-2990
                 URL: https://issues.apache.org/jira/browse/LOG4J2-2990
             Project: Log4j 2
          Issue Type: Improvement
          Components: SLF4J Bridge
    Affects Versions: 2.14.0, 3.0.0
            Reporter: Diogo Monteiro


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:

{code:java}
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)
}
{code}
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 at the beginning, 2 for each {{await()}}.

I noticed that in the [Log4jMDCAdapter implementation|https://github.com/apache/logging-log4j2/blob/master/log4j-slf4j-impl/src/main/java/org/apache/logging/slf4j/Log4jMDCAdapter.java#L58], [ThreadContext.put|https://github.com/apache/logging-log4j2/blob/d9e01a981b860aeb8834eac3eed201c686884b7a/log4j-api/src/main/java/org/apache/logging/log4j/ThreadContext.java#L244] 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:

{code:java}
// 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);
    }
{code}

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.



--
This message was sent by Atlassian Jira
(v8.3.4#803005)