[JIRA] Created: (LBCLASSIC-153) Excessive synchronization in ReconfigureOnChangeFilter.decide
Excessive synchronization in ReconfigureOnChangeFilter.decide ------------------------------------------------------------- Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Logback dev list The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration. -- 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-153?page=com.atlassian.jira.plugin.syste... ] Anders Wallgren updated LBCLASSIC-153: -------------------------------------- Attachment: screenshot-1.jpg Monitor contention on a 4-cpu run in YourKit profiler.
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Logback dev list Attachments: screenshot-1.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu commented on LBCLASSIC-153: -------------------------------------- Sorry but I can't make sense out of the screenshot. What does it say? (A phrase or two describing the screenshot should be enough.)
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Logback dev list Attachments: screenshot-1.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-153: --------------------------------------- On the top you will see that 4% of the overall CPU time is spent while holding the lock for LoggerContext (61,895 ms). The bottom window just shows how it was called.
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Ceki Gulcu Attachments: screenshot-1.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ralph Goers edited comment on LBCLASSIC-153 at 9/24/09 10:06 AM: ----------------------------------------------------------------- On the top you will see that 4% of the overall CPU time is spent while holding the lock for LoggerContext (61,895 ms). The bottom window just shows how it was called. A way to solve this issue as well as LBCLASSIC-154 would be to change the TurboFilter to have a Timer and TimerTask that periodically wakes up and checks the file timestamp. If it is newer then it calls reconfigure while holding a write lock. The turbo filter would only acquire the read lock and then immediately release it so that logging will block when a reconfigure occurs. While no reconfiguration is taking place threads would not block at all on the read lock. was (Author: rgoers@apache.org): On the top you will see that 4% of the overall CPU time is spent while holding the lock for LoggerContext (61,895 ms). The bottom window just shows how it was called.
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Ceki Gulcu Attachments: screenshot-1.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu closed LBCLASSIC-153. -------------------------------- Resolution: Cannot Reproduce Hello, I have tried to reproduce this bug by creating a relevant test case, called ReconfigurePerf, part of the ch.qos.logback.classic.turbo package (in src/test) and measuring its performance on 4 core CPU with 5 threads. JProfiler showed that only a marginal percentage of CPU was spent in ReconfigureOnChangeFilter's decide method. Using Yourkit yielded similar results. So, either 1) ReconfigurePerf is non-representative 2) I misused the profiler 3) your tests are non-representative In the mean-time I am marking this bug as "Cannot reproduce". If after profiling ReconfigurePerf you obtain a different result, or you detect an error in the test, do not hesitate to reopen this report.
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Ceki Gulcu Attachments: screenshot-1.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu reopened LBCLASSIC-153: ----------------------------------
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Ceki Gulcu Attachments: jprofiler.jpg, screenshot-1.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu updated LBCLASSIC-153: --------------------------------- Attachment: jprofiler.jpg
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Ceki Gulcu Attachments: jprofiler.jpg, screenshot-1.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu updated LBCLASSIC-153: --------------------------------- Attachment: yourkit.jpg
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Ceki Gulcu Attachments: jprofiler.jpg, screenshot-1.jpg, yourkit.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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-153?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu closed LBCLASSIC-153. -------------------------------- Resolution: Fixed
Excessive synchronization in ReconfigureOnChangeFilter.decide -------------------------------------------------------------
Key: LBCLASSIC-153 URL: http://jira.qos.ch/browse/LBCLASSIC-153 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Reporter: Anders Wallgren Assignee: Ceki Gulcu Attachments: jprofiler.jpg, screenshot-1.jpg, yourkit.jpg
The synchronization in ReconfigureOnChangeFilter.decide hurts scalability. It seems unnecessary to serialize the code in changeDetected -- it should be possible to use atomic updates of nextCheck and lastModified and only serialize the actual reconfiguration.
-- 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 (3)
-
Anders Wallgren (JIRA) -
Ceki Gulcu (JIRA)
-
Ralph Goers (JIRA)