logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (LOG4J2-1611) Improve performance of ThreadContextDataInjector.ForDefaultThreadContextMap
Date Sun, 25 Sep 2016 00:48:20 GMT

    [ 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 9/25/16 12:47 AM:
---------------------------------------------------------------

When I ran the JMH ThreadContextBenchmark I found a performance problem when merging context
data with properties. This is now addressed. 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.


was (Author: remkop@yahoo.com):
When I ran the JMH ThreadContextBenchmark I found a performance problem when merging context
data with properties. This is now addressed. 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!
----
!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: InjectWithProperties.png, InjectWithoutProperties.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.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message