[
https://issues.apache.org/jira/browse/LOG4J2-2671?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Luke Butters updated LOG4J2-2671:
---------------------------------
Description:
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 exiting {{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!
was:
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 exiting }}{{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!
> 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 exiting {{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
(v7.6.14#76016)
