[JIRA] Created: (LBCLASSIC-254) Performance improvement for LogbackMDCAdapter
Performance improvement for LogbackMDCAdapter --------------------------------------------- Key: LBCLASSIC-254 URL: http://jira.qos.ch/browse/LBCLASSIC-254 Project: logback-classic Issue Type: Improvement Components: Other Affects Versions: 0.9.28 Reporter: Michael Franz Assignee: Logback dev list Attachments: LogbackMDCAdapter.java During performance analysis of our application the LogbackMDCAdapter showed up as a performance hotspot. This is because the application does relatively often replaces multiple entries in the MDC at ones, e.g. 6 removes/writes without any intermediate log statement. Also actual log messages that come through filtering before creating the LoggingEvent are relatively rare in production environments. I have reworked the implementation to improve the performance. The main idea is to defer cloning the internal Map as long possible. This patch increased overall application performance by about 10% in that test. Other application types were MDC changes are small and many LoggingEvent objects are created (calls to getPropertyMap()) should not be affected significantly. Note: I haven't check if my patch would reintroduce the #LBCLASSIC-183, but my subclasses of InheritableThreadLocal does not override the initialValue() method, so it could work. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-254?page=com.atlassian.jira.plugin.syste... ] Michael Franz updated LBCLASSIC-254: ------------------------------------ Attachment: LogbackMDCAdapter.java
Performance improvement for LogbackMDCAdapter ---------------------------------------------
Key: LBCLASSIC-254 URL: http://jira.qos.ch/browse/LBCLASSIC-254 Project: logback-classic Issue Type: Improvement Components: Other Affects Versions: 0.9.28 Reporter: Michael Franz Assignee: Logback dev list Attachments: LogbackMDCAdapter.java
During performance analysis of our application the LogbackMDCAdapter showed up as a performance hotspot. This is because the application does relatively often replaces multiple entries in the MDC at ones, e.g. 6 removes/writes without any intermediate log statement. Also actual log messages that come through filtering before creating the LoggingEvent are relatively rare in production environments. I have reworked the implementation to improve the performance. The main idea is to defer cloning the internal Map as long possible. This patch increased overall application performance by about 10% in that test. Other application types were MDC changes are small and many LoggingEvent objects are created (calls to getPropertyMap()) should not be affected significantly. Note: I haven't check if my patch would reintroduce the #LBCLASSIC-183, but my subclasses of InheritableThreadLocal does not override the initialValue() method, so it could work.
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-254?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu reassigned LBCLASSIC-254: ------------------------------------ Assignee: Ceki Gulcu (was: Logback dev list)
Performance improvement for LogbackMDCAdapter ---------------------------------------------
Key: LBCLASSIC-254 URL: http://jira.qos.ch/browse/LBCLASSIC-254 Project: logback-classic Issue Type: Improvement Components: Other Affects Versions: 0.9.28 Reporter: Michael Franz Assignee: Ceki Gulcu Attachments: LogbackMDCAdapter.java
During performance analysis of our application the LogbackMDCAdapter showed up as a performance hotspot. This is because the application does relatively often replaces multiple entries in the MDC at ones, e.g. 6 removes/writes without any intermediate log statement. Also actual log messages that come through filtering before creating the LoggingEvent are relatively rare in production environments. I have reworked the implementation to improve the performance. The main idea is to defer cloning the internal Map as long possible. This patch increased overall application performance by about 10% in that test. Other application types were MDC changes are small and many LoggingEvent objects are created (calls to getPropertyMap()) should not be affected significantly. Note: I haven't check if my patch would reintroduce the #LBCLASSIC-183, but my subclasses of InheritableThreadLocal does not override the initialValue() method, so it could work.
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-254?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu commented on LBCLASSIC-254: -------------------------------------- Hi Michael, After looking at your code, I got an idea and was wondering if it would meet your needs. Instead of keeping two maps, we keep a single map but copy it only if necessary. All we need for efficient/timely copying is a variable keeping track of the last operation. A copy is necessary on 'put' or 'remove' but only if the last operation was a 'get'.Get operations never necessitate a copy nor successive 'put/remove' operations, only a get followed by a 'put/remove' requires copying the map. With that in mind, let (m, 'op') designate the tuple consisting of hashMap 'm' and last operation 'op'. So, for example, "put: (m1, 'get') -> (m2, 'put')" states that in response to a put operation the map m1 is transformed into a new map m2. The lastOperation variable is changed from 'get' to 'put'. Here is an illustration of changes into the MDC structure with this notation: put: (null, null) -> (m0, 'put') put: (m0, 'put') -> (m0, 'put) get: (m0, 'get') -> (m0, 'get') get: (m0, 'get') -> (m0, 'get') remove: (m0, 'get') -> (m1, 'remove') get: (m1, 'remove') -> (m1, 'get') get: (m1, 'get') -> (m1, 'get') remove: (m1, 'get') -> (m2, 'remove') ... and so on Note that 8 operations were performed by only 3 maps were created. What do you think?
Performance improvement for LogbackMDCAdapter ---------------------------------------------
Key: LBCLASSIC-254 URL: http://jira.qos.ch/browse/LBCLASSIC-254 Project: logback-classic Issue Type: Improvement Components: Other Affects Versions: 0.9.28 Reporter: Michael Franz Assignee: Ceki Gulcu Attachments: LogbackMDCAdapter.java
During performance analysis of our application the LogbackMDCAdapter showed up as a performance hotspot. This is because the application does relatively often replaces multiple entries in the MDC at ones, e.g. 6 removes/writes without any intermediate log statement. Also actual log messages that come through filtering before creating the LoggingEvent are relatively rare in production environments. I have reworked the implementation to improve the performance. The main idea is to defer cloning the internal Map as long possible. This patch increased overall application performance by about 10% in that test. Other application types were MDC changes are small and many LoggingEvent objects are created (calls to getPropertyMap()) should not be affected significantly. Note: I haven't check if my patch would reintroduce the #LBCLASSIC-183, but my subclasses of InheritableThreadLocal does not override the initialValue() method, so it could work.
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-254?page=com.atlassian.jira.plugin.syste... ] Michael Franz commented on LBCLASSIC-254: ----------------------------------------- Hello Ceki, I've looked over the whole application code and actually there is only one very rarely called get-operation on the MDC. So your approach would also work in my scenario. But as a software developer I would feel a bit uncomfortable with your strategy: "copy on write after read" sounds quite uncommon against "copy on write" and "lazy copy". With your approach you are forcing developers to keep an eye on the order of put- and get-operations, especially if an application performs existence checks before writing on the MDC. As long as only puts are performed (like in my case) your approach is sufficient. I don't know if there are real world applications that often call gets. Nevertheless this is just a feeling.
Performance improvement for LogbackMDCAdapter ---------------------------------------------
Key: LBCLASSIC-254 URL: http://jira.qos.ch/browse/LBCLASSIC-254 Project: logback-classic Issue Type: Improvement Components: Other Affects Versions: 0.9.28 Reporter: Michael Franz Assignee: Ceki Gulcu Attachments: LogbackMDCAdapter.java
During performance analysis of our application the LogbackMDCAdapter showed up as a performance hotspot. This is because the application does relatively often replaces multiple entries in the MDC at ones, e.g. 6 removes/writes without any intermediate log statement. Also actual log messages that come through filtering before creating the LoggingEvent are relatively rare in production environments. I have reworked the implementation to improve the performance. The main idea is to defer cloning the internal Map as long possible. This patch increased overall application performance by about 10% in that test. Other application types were MDC changes are small and many LoggingEvent objects are created (calls to getPropertyMap()) should not be affected significantly. Note: I haven't check if my patch would reintroduce the #LBCLASSIC-183, but my subclasses of InheritableThreadLocal does not override the initialValue() method, so it could work.
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
[ http://jira.qos.ch/browse/LBCLASSIC-254?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu resolved LBCLASSIC-254. ---------------------------------- Fix Version/s: 0.9.29 Resolution: Fixed I just committed a patch [1] which fixes this performance issue as well as another yet unreported bug. [1] http://github.com/ceki/logback/commit/e068bd3b9754e8d6
Performance improvement for LogbackMDCAdapter ---------------------------------------------
Key: LBCLASSIC-254 URL: http://jira.qos.ch/browse/LBCLASSIC-254 Project: logback-classic Issue Type: Improvement Components: Other Affects Versions: 0.9.28 Reporter: Michael Franz Assignee: Ceki Gulcu Fix For: 0.9.29
Attachments: LogbackMDCAdapter.java
During performance analysis of our application the LogbackMDCAdapter showed up as a performance hotspot. This is because the application does relatively often replaces multiple entries in the MDC at ones, e.g. 6 removes/writes without any intermediate log statement. Also actual log messages that come through filtering before creating the LoggingEvent are relatively rare in production environments. I have reworked the implementation to improve the performance. The main idea is to defer cloning the internal Map as long possible. This patch increased overall application performance by about 10% in that test. Other application types were MDC changes are small and many LoggingEvent objects are created (calls to getPropertyMap()) should not be affected significantly. Note: I haven't check if my patch would reintroduce the #LBCLASSIC-183, but my subclasses of InheritableThreadLocal does not override the initialValue() method, so it could work.
-- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
participants (2)
-
Ceki Gulcu (JIRA) -
Michael Franz (JIRA)