You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Diogo Monteiro (Jira)" <ji...@apache.org> on 2021/01/05 18:30:00 UTC
[jira] [Updated] (LOG4J2-2990) Make use of ThreadContext.putAll on
SLF4j MDCAdapter
[ https://issues.apache.org/jira/browse/LOG4J2-2990?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Diogo Monteiro updated LOG4J2-2990:
-----------------------------------
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:
{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.
was:
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.
> 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: 3.0.0, 2.14.0
> Reporter: Diogo Monteiro
> Priority: Minor
>
> 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)