[JIRA] Created: (LBCLASSIC-234) CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide

CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
--------------------------------------------------------------------

                 Key: LBCLASSIC-234
                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
             Project: logback-classic
          Issue Type: Bug
    Affects Versions: 0.917
            Reporter: uri unger
            Assignee: Ceki Gulcu


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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11900#action_11900 ]

uri unger commented on LBCLASSIC-234:
-------------------------------------

hello there Ceki,

I have cloned this issue because we have stumbled into a very similar scenario in our production system.

we have a web app running inside tomcat that uses 4000 concurrent threads.
when we enable scanPeriod, we get around 6,000 transactions per second. if we simply disable file scanning entirely, we get 12,000 TPS.
granted, this is a real issue for us, and it forces us to use the non-scanning mode.

ofcourse, i have read the LBCLASSIC-154 bug, and currently i'm trying to regenerate our problem using your ReconfigurePerf test,.
however,  the mean while, i would sure like to hear your thoughts on this matter.

we use the latest logback (0.9.26).

thanks alot
uri@amobee

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>
> 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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11901#action_11901 ]

uri unger commented on LBCLASSIC-234:
-------------------------------------

(i meant LBCLASSIC-153 bug... i dont seem to find how to edit my comments)

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>
> 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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

     [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

uri unger updated LBCLASSIC-234:
--------------------------------

    Comment: was deleted

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>
> 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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11900#action_11900 ]

uri unger edited comment on LBCLASSIC-234 at 11/23/10 1:55 PM:
---------------------------------------------------------------

hello there Ceki,

I have cloned this issue because we have stumbled into a very similar scenario in our production system.

we have a web app running inside tomcat that uses 4000 concurrent threads.
when we enable scanPeriod, we get around 6,000 transactions per second. if we simply disable file scanning entirely, we get 12,000 TPS.
granted, this is a real issue for us, and it forces us to use the non-scanning mode.

ofcourse, i have read the LBCLASSIC-153 bug, and currently i'm trying to regenerate our problem using your ReconfigurePerf test,.
however,  the mean while, i would sure like to hear your thoughts on this matter.

we use the latest logback (0.9.26).

thanks alot
uri@amobee

      was (Author: uriunger):
    hello there Ceki,

I have cloned this issue because we have stumbled into a very similar scenario in our production system.

we have a web app running inside tomcat that uses 4000 concurrent threads.
when we enable scanPeriod, we get around 6,000 transactions per second. if we simply disable file scanning entirely, we get 12,000 TPS.
granted, this is a real issue for us, and it forces us to use the non-scanning mode.

ofcourse, i have read the LBCLASSIC-154 bug, and currently i'm trying to regenerate our problem using your ReconfigurePerf test,.
however,  the mean while, i would sure like to hear your thoughts on this matter.

we use the latest logback (0.9.26).

thanks alot
uri@amobee
 

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>
> 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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

     [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Ceki Gulcu updated LBCLASSIC-234:
---------------------------------

    Priority: Critical  (was: Major)

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>
> 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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11902#action_11902 ]

uri unger commented on LBCLASSIC-234:
-------------------------------------

Ok, now regarding regenerating this bug using your ReconfigurePerf  test.

I have made several minor changes in your test code as follows:
1. totalTestDuration was very short, only 1100 ms (i'm testing on windows); i changed it to something like a few minutes to allow me to actually see something in jprofiler.
2. very important: in scan_perf.xml, i have changed the default root level from debug to error. this is becuase I must not really write any log to any file, or otherwise the io times would  dominate the running time and i won't be able to see any significant finding regarding the issue in the profiler.

Sure enough, after doing these changes, i see locking times of more than 200ms using only 50 concurrent threads in jprofiler.
I also added a screen capture of the threads as seen in the thread history view in fprofiler. the little red sections are the blocking times.

uri

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

     [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

uri unger updated LBCLASSIC-234:
--------------------------------

    Attachment: screenshot-1.jpg

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11902#action_11902 ]

uri unger edited comment on LBCLASSIC-234 at 11/23/10 4:53 PM:
---------------------------------------------------------------

Ok, now regarding regenerating this bug using your ReconfigurePerf  test.

I have made several minor changes in your test code as follows:
1. totalTestDuration was very short, only 1100 ms (i'm testing on windows); i changed it to something like a few minutes to allow me to actually see something in jprofiler.
2. very important: in scan_perf.xml, i have changed the default root level from debug to error. This is becuase I must not really write any log to any file, or otherwise the io times would  dominate the running time and i won't be able to see any significant finding regarding the issue in the profiler.

Sure enough, after doing these changes, i see (in jprofiler) locking times of more than 200ms using only 50 concurrent threads.
I've also added a screen capture of the threads history view in jprofiler. The little red sections are the blocking times.

uri


      was (Author: uriunger):
    Ok, now regarding regenerating this bug using your ReconfigurePerf  test.

I have made several minor changes in your test code as follows:
1. totalTestDuration was very short, only 1100 ms (i'm testing on windows); i changed it to something like a few minutes to allow me to actually see something in jprofiler.
2. very important: in scan_perf.xml, i have changed the default root level from debug to error. this is becuase I must not really write any log to any file, or otherwise the io times would  dominate the running time and i won't be able to see any significant finding regarding the issue in the profiler.

Sure enough, after doing these changes, i see locking times of more than 200ms using only 50 concurrent threads in jprofiler.
I also added a screen capture of the threads as seen in the thread history view in fprofiler. the little red sections are the blocking times.

uri

 

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11903#action_11903 ]

Ralph Goers commented on LBCLASSIC-234:
---------------------------------------

One of the design issues in this was how to use threads.  Managing threads has proven to be troublesome and is something the design of logback has avoided doing. I say this because an alternative approach to this is to use a servlet filter to create a thread that periodically determines if a reconfigure is necessary. This removes the bottleneck you are seeing because scanning will be disabled during normal Logback processing. However, because it is a servlet filter it can't be configured by logback.

The projects I work with all use this technique instead of the turbo filter.

I should also point out that while reconfiguration is taking place logging some logging events will be lost or possibly incorrectly handled. Reconfiguration stops all appenders and filters (but does not remove loggers added by the previous configuration) and then runs through the new configuration enabling filters and appenders as they are encountered.

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11904#action_11904 ]

Ceki Gulcu commented on LBCLASSIC-234:
--------------------------------------

Hello Uri,

The fact that  scanning reduces throughput by 50% is rather disturbing. Can you test throughput of your application with  line 107 of
ReconfigureOnChangeFilter changed
from:
 if (((invocationCounter++) & 0xF) != 0xF) {
to:
 if (((invocationCounter++) & 0xFFFF) != 0xFFFF) {

Do you see a noticeable difference?

BTW, what is your target OS?
 

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11905#action_11905 ]

uri unger commented on LBCLASSIC-234:
-------------------------------------

Ceki,

I can not easily change that line, re-package logback and our application, redeploy our application and re-run a full performance test. It is quite complex.
However, I did try to rerun ReconfigurePerf  after making your suggested change; and indeed the maximal thread contention time droped to10-12ms (instead of 200+ ms).

Still, I think that using a simple scheduled config file check (using java's ScheduledThreadPoolExecutor for example) is a much better solution that would remove the synchronization penalty almost entirely. Are you considering using such a solution?

Ralph,

We are aware that we can turn off scanning in logback and implement it ourselves using our own thread. However, I'm sure that any sensible user of logback would prefer to have this functionality built-in without having to resort to in-house workarounds.

uri

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11906#action_11906 ]

Ceki Gulcu commented on LBCLASSIC-234:
--------------------------------------

I actually spent a few hours yesterday investigating this problem. I would be happy to make the necessary changes once the point of contention is clearly identified. Changing line 107 as suggested above would be very helpful in that regard.

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12334#action_12334 ]

Niklas Therning commented on LBCLASSIC-234:
-------------------------------------------

Hi,

I think we're experiencing this problem too. Our application constantly monitors thousands of users' POP3 and IMAP mailboxes and removes spam. About every 24 hours we have to restart our application. We've had a look at thread dumps taken just before a restart and we're seeing that most of our worker threads are waiting to obtain a lock in ReconfigureOnChangeFilter (see below for an example).

I'd like to help out with this issue. Should I make a patched version with the suggested 0xFFFF fix and see if there's any difference? Should I patch 0.9.7 or a later version? There seems to have been quite a few changes in 1.0 and latest trunk to ReconfigureOnChangeFilter (though the synchronization is still there).

Also, regarding fixing this problem, nextCheck in ReconfigureOnChangeFilter has been made volatile since 0.9.7. Wouldn't it be safe to just check changeDetected() twice? Once outside the synchronized block and then again inside?

We're running on Debian Squeeze and Debian Lenny.

Example from thread dump:
"Worker-22" prio=10 tid=0x00007f4d88cf6800 nid=0x5c2e waiting for monitor entry [0x00007f4d7dad9000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.decide(ReconfigureOnChangeFilter.java:99)
        - waiting to lock <0x00000000c078fec8> (a ch.qos.logback.classic.LoggerContext)
        at ch.qos.logback.classic.spi.TurboFilterList.getTurboFilterChainDecision(TurboFilterList.java:47)
        at ch.qos.logback.classic.LoggerContext.getTurboFilterChainDecision_0_3OrMore(LoggerContext.java:251)
        at ch.qos.logback.classic.Logger.callTurboFilters(Logger.java:770)
        at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:488)
        at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:484)

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://mailman.qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12341#action_12341 ]

Stuart Roebuck commented on LBCLASSIC-234:
------------------------------------------

Just by way of confirmation I too have been encountering this issue.  It took me a long time to track down, largely because I just wasn't expecting logback to be the issue.  Like Niklas, I found that our server would typically lock up within any 48 hour period and basically needed a restart.  Thread dumps showed the code locked on ch.qos.logback.core.joran.spi.ConfigurationWatchList in ReconfigureOnChangeFilter.java

I'm using LogBack 1.0.0

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://mailman.qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12387#action_12387 ]

Tim Lark commented on LBCLASSIC-234:
------------------------------------

Another confirmation (0.9.26).  Our app maxes out the thread pool (250) within 2 minutes during a load test (5 requests/sec) and we're getting many complaints in the field of significant latency issues due to this.

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://mailman.qos.ch/mailman/listinfo/logback-dev

    [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12396#action_12396 ]

Ceki Gulcu commented on LBCLASSIC-234:
--------------------------------------

I am happy to report that I am now able to reproduce this problem. Changing the root level from DEBUG to ERROR was key. As explained by Uri Unger, if logging is enabled, then I/O times dominate everything else.

A fix is on the way.

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://mailman.qos.ch/mailman/listinfo/logback-dev

     [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Ceki Gulcu resolved LBCLASSIC-234.
----------------------------------

    Fix Version/s: 1.0.2
       Resolution: Fixed

Fixed in http://github.com/ceki/logback/commit/608ed4c58717296

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>             Fix For: 1.0.2
>
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://mailman.qos.ch/mailman/listinfo/logback-dev

     [ http://jira.qos.ch/browse/LBCLASSIC-234?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Ceki Gulcu updated LBCLASSIC-234:
---------------------------------

    Comment: was deleted

> CLONE -Excessive synchronization in ReconfigureOnChangeFilter.decide
> --------------------------------------------------------------------
>
>                 Key: LBCLASSIC-234
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-234
>             Project: logback-classic
>          Issue Type: Bug
>    Affects Versions: 0.917
>            Reporter: uri unger
>            Assignee: Ceki Gulcu
>            Priority: Critical
>             Fix For: 1.0.2
>
>         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

       
_______________________________________________
logback-dev mailing list
logback-dev@...
http://mailman.qos.ch/mailman/listinfo/logback-dev