[
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: [email protected]):
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)
