You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2017/06/29 01:40:00 UTC
[jira] [Comment Edited] (LOG4J2-1611) Improve performance of
ThreadContextDataInjector.ForDefaultThreadContextMap
[ https://issues.apache.org/jira/browse/LOG4J2-1611?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15519381#comment-15519381 ]
Remko Popma edited comment on LOG4J2-1611 at 6/29/17 1:39 AM:
--------------------------------------------------------------
Updated benchmark results follow below.
----
h3. Injecting ThreadContext data into LogEvent
Every time the application logs something, ThreadContext key-value pairs are copied into the LogEvent (see [LogEvent.getContextData()|https://logging.apache.org/log4j/2.x/log4j-core/apidocs/org/apache/logging/log4j/core/LogEvent.html#getContextData]). This is called "context data injection".
This happens for each event so must be fast. The "Default" data structure is immutable and can be passed by reference to the LogEvent. The "NoGc" data structures are mutable so need to be copied.
Below analyses the performance difference between these data structures.
!InjectWithoutProperties.png!
5: context data has 5 elements
50: context data has 50 elements
500: context data has 500 elements
"Default (map to ctxtdata)" is the JdkMapAdapterStringMap wrapper around the Map<String,String> thread context copy. This is much faster than in a previous (erroneous) performance test when the Map was copied into a SortedArray data structure (see below).
The "Copy" variants are fast because they already copied the data structure on ThreadContext::put() or ThreadContext::remove(), and now they just pass a reference. The NoGc variants need to copy the data structure. SortedArray is faster to copy than the OpenHash data structure.
h3. Old erroneous version (before the fix)
!https://issues.apache.org/jira/secure/attachment/12825061/12825061_v2_InjectWithoutConfigProperties.png!
----
h3. Injecting context data merged with logger properties
Injecting context data while the logger has properties configured is very different. The thread context data may or may not enforce immutability, but the injector _must_ copy the data into a different data structure and also merge in the properties values.
Early [benchmark results|https://issues.apache.org/jira/browse/LOG4J2-1349?focusedCommentId=15432877&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15432877] are *invalid*: they were run with a version of SortedArrayStringMap (then called ArrayContextData) that did not correctly merge properties with context data.
The results below are for the correct data structure after optimization:
!InjectWithProperties.png!
Same as above, with 5 properties that need to be merged with the context data.
"Default (map to ctxtdata)" creates a mutable copy of the Map<String,String> thread context and wraps it in a JdkMapAdapterStringMap before adding the property key-values. (Previously the implementation copied from the Map into a SortedArray, which was _slow_ because the Map iterator does not return the keys in alphabetic order.)
(Please ignore the CopyOpenHash result; this data structure is only for benchmarking. It demonstrates how slow it can be to copy unsorted data in a SortedArray.)
----
h3. Modifying the ThreadContext
We assume there are many more "reads from" than "writes to" the ThreadContext (reads-from is logging: injecting key-value pairs into a LogEvent, writes-to is the application putting or removing key-value pairs in the ThreadContext).
For this reason, the "Default" implementation uses a copy-on-write data structure that is expensive to modify but cheap to copy (can be passed by reference because it is immutable).
!ThreadContext-PutAndRemove.png!
5: put one new key-value pair, then remove it from a ThreadContext with 5 elements
50: put one new key-value pair, then remove it from a ThreadContext with 50 elements
500: put one new key-value pair, then remove it from a ThreadContext with 500 elements
Put and remove is expensive for the SortedArray variants because the remainder of the array needs to be copied one position to the left or right, but this is cheap compared to the copy-on-write map implementations that need to copy the whole data structure.
----
!ThreadContext-Get.png!
SortedArray uses binary search which is a bit slower than the hash-based data structures.
I am looking at speeding this up (LOG4J2-1607) by maintaining an additional hash index in SortedArrayStringMap.
was (Author: remkop@yahoo.com):
Updated benchmark results follow below.
----
!InjectWithoutProperties.png!
5: context data has 5 elements
50: context data has 50 elements
500: context data has 500 elements
"Default (map to ctxtdata)" is the JdkMapAdapterStringMap wrapper around the Map<String,String> thread context copy. This is much faster than previously when the Map was copied into a SortedArray data structure (see below).
The "Copy" variants are fast because they already copied the data structure on ThreadContext::put() or ThreadContext::remove(), and now they just pass a reference. The NoGc variants need to copy the data structure. SortedArray benefits from being compact.
h3. Old version (before the fix)
!https://issues.apache.org/jira/secure/attachment/12825061/12825061_v2_InjectWithoutConfigProperties.png!
----
h3. Injecting context data merged with logger properties
Injecting context data while the logger has properties configured is very different. The thread context data may or may not enforce immutability, but the injector _must_ copy the data into a different data structure and also merge in the properties values.
Early [benchmark results|https://issues.apache.org/jira/browse/LOG4J2-1349?focusedCommentId=15432877&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-15432877] are *invalid*: they were run with a version of SortedArrayStringMap (then called ArrayContextData) that did not correctly merge properties with context data.
The results below are for the correct data structure after optimization:
!InjectWithProperties.png!
Same as above, with 5 properties that need to be merged with the context data.
"Default (map to ctxtdata)" creates a mutable copy of the Map<String,String> thread context and wraps it in a JdkMapAdapterStringMap before adding the property key-values. (Previously the implementation copied from the Map into a SortedArray, which was _slow_ because the Map iterator does not return the keys in alphabetic order.)
(Please ignore the CopyOpenHash result; this data structure is only for benchmarking. It demonstrates how slow it can be to copy unsorted data in a SortedArray.)
----
!ThreadContext-PutAndRemove.png!
5: put one new key-value pair, then remove it from a ThreadContext with 5 elements
50: put one new key-value pair, then remove it from a ThreadContext with 50 elements
500: put one new key-value pair, then remove it from a ThreadContext with 500 elements
Put and remove is expensive for the SortedArray variants because the remainder of the array needs to be copied one position to the left or right, but this is cheap compared to the copy-on-write map implementations that need to copy the whole data structure.
----
!ThreadContext-Get.png!
SortedArray uses binary search which is a bit slower than the hash-based data structures.
I am looking at speeding this up (LOG4J2-1607) by maintaining an additional hash index in SortedArrayStringMap.
> Improve performance of ThreadContextDataInjector.ForDefaultThreadContextMap
> ---------------------------------------------------------------------------
>
> Key: LOG4J2-1611
> URL: https://issues.apache.org/jira/browse/LOG4J2-1611
> Project: Log4j 2
> Issue Type: Improvement
> Components: Core
> Affects Versions: 2.7
> Reporter: Remko Popma
> Assignee: Remko Popma
> Fix For: 2.7
>
> Attachments: InjectWithoutProperties.png, InjectWithProperties.png, ThreadContext-Get.png, ThreadContext-PutAndRemove.png
>
>
> Current implementation of {{ThreadContextDataInjector.ForDefaultThreadContextMap::injectContextData}} always copies all elements from the ThreadContext into the reused StringMap of the LogEvent.
> Since the DefaultThreadContextMap is used in web applications (when non-JDK thread-locals are not available and Log4j is not garbage-free), we don't need to worry about creating additional objects. We can speed up the {{injectContextData}} method by wrapping the context data {{Map<String, String>}} in a decorator object that implements the {{StringMap}} interface.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)