[jira] [Commented] (LOG4J2-2671) Improve the performance of adding and removing multiple values from the ThreadContext

["Ralph Goers (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4J2-2671?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16989403#comment-16989403 ] 

Ralph Goers commented on LOG4J2-2671:
-------------------------------------

The expected usage is that your would add several items to the ThreadContextMap and then they would be referenced many times before they are removed from the map.  The map, or its contents, has to be copied for each event that is logged. So the code was optimized to make the copies fast. Of course, if there improvements that can be made to put and remove that is great.

I am also a little confused by your proposal as DefaultThreadContextMap already has a putAll and RemoveAll that work similarly to your code above.

> Improve the performance of adding and removing multiple values from the ThreadContext
> -------------------------------------------------------------------------------------
>
>                 Key: LOG4J2-2671
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-2671
>             Project: Log4j 2
>          Issue Type: Improvement
>            Reporter: Luke Butters
>            Priority: Major
>         Attachments: Screenshot_20190810_090546.png, Screenshot_20190810_090710.png
>
>
> I notice in profiling that a bunch of time is spent under ThreadContext specifically in DefaultThreadContextMap.
> What my code does is put a few things into the map e.g.
> {code:java}
> ThreadContext.put("a", "b");{code}
> This actually results in [DefaultThreadContextMap|https://github.com/apache/logging-log4j2/blob/master/log4j-api/src/main/java/org/apache/logging/log4j/spi/DefaultThreadContextMap.java#L83] creating a copy of the existing map, updating that copy and setting it back. So if I want to set 5 things we end up copying the map 4 times.
>  This also happens when calling:
> {code:java}
> ThreadContext.remove("a");{code}
> What could be done instead is for {{ThreadContext}} to take multiple values similar to the existing {{putAll}} available on {{Map}} that way I can pass in all values at once avoiding making (n -1) copies of the Map. It might make sense for this method to take a {{Collection}} of {{Map.Entry}} as that way the caller doesn't need to construct a Map and can instead construct a cheaper list of Entries to be added to the map.
> some sample code of how this would look:
> {code:java}
>     public void putAll(Collection<Map.Entry<String, String>> toAdd) {
>         if (!useMap) {
>             return;
>         }
>         Map<String, String> map = localMap.get();
>         map = map == null ? new HashMap<String, String>() : new HashMap<>(map);
>         for(Map.Entry<String, String> e : toAdd) {
>             map.put(e.getKey(), e.getValue());
>         }
>         localMap.set(Collections.unmodifiableMap(map));
>     }{code}
> The remove method should also be improved to take a List entries that way we can avoid making multiple copies of the map an example of how this might look:
> {code:java}
>     public void remove(final Collection<String> keys) {
>         final Map<String, String> map = localMap.get();
>         if (map != null) {
>             final Map<String, String> copy = new HashMap<>(map);
>             for(String key : keys) {
>                 copy.remove(key);
>             }
>             localMap.set(Collections.unmodifiableMap(copy));
>         }
>     }{code}
>  
> Running a test which attempts to add 5 values and then remove those 5 values 1 million times, repeated ten times. I then averaged the results of how long that took for all ten results to come up with:
>  *current:* 1093ms
> *new:* 310ms
> Here are the visualvm profiling results of what log4j currently has:
> Adding:
> !Screenshot_20190810_090710.png!
> Removal:
> !Screenshot_20190810_090546.png!



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