[logback-dev] [JIRA] Issue Comment Edited: (LBCLASSIC-35) Deadlock when running on multiple core processors

[Ralph Goers (JIRA)]

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

Ralph Goers edited comment on LBCLASSIC-35 at 10/14/08 9:05 PM:
----------------------------------------------------------------

Well, that was silly. Of course I should have removed the synchronization on the logger in callAppenders. I can't believe I didn't do that since that was the whole point.

Yes, requiring Appenders to have immutable names that are set before the appender is attached will make AppenderAttachableImpl much simpler since the name can then reliably be used in the ConcurrentMap. The extra code to account for the name being missing can just go away.

As for the synchronization in addAppender, it is marginally better since it doesn't block aai.addAppender. The synchronization it is still doing only protects against a race condition on creating the AppenderAttachableImpl. However, this might not not even occur.

My concern is for what happens when a reconfigure occurs. Is it possible that a Logger didn't have an AppenderAttachableImpl (i.e. it has no Appenders) and then does after a reconfigure? If so, then aai may need to be an AtomicReference. I haven't looked at how the Interpreter works and how loggers get updated, etc.so I'm not sure.

I appreciate you looking at the code. Multiple pairs of eyeballs are always better than 1 set.

      was (Author: rgoers at apache.org):
    Well, that was silly. Of course I should have removed the synchronization on the logger in callAppenders. I can't believe I didn't do that since that was the whole point.

Yes, requiring Appenders to have immutable names that are set before the appender is attached will make AppenderAttachableImpl much simpler since the name can then reliably be used in the ConcurrentMap. The extra code to account for the name being missing can just go away.

As for the synchronization in addAppender, it is marginally better since it doesn't block aai.addAppender. The synchronization it is still doing only protects against a race condition on creating the AppenderAttachableImpl. However, this might not not even occur.

My concern is for what happens when a reconfigure occurs. Is it possible that a Logger didn't have an AppenderAttachableImpl (i.e. it has not Appenders) and then does after a reconfigure? If so, then aai may need to be an AtomicReference. I haven't looked at how the Interpreter works and how loggers get updated, etc.so I'm not sure.

I appreciate you looking at the code. Multiple pairs of eyeballs are always better than 1 set.
  
> Deadlock when running on multiple core processors
> -------------------------------------------------
>
>                 Key: LBCLASSIC-35
>                 URL: http://jira.qos.ch/browse/LBCLASSIC-35
>             Project: logback-classic
>          Issue Type: Bug
>          Components: Other
>    Affects Versions: unspecified
>         Environment: Operating System: Windows
> Platform: PC
>            Reporter: Toni Heimala
>            Assignee: Ceki Gulcu
>            Priority: Blocker
>         Attachments: patch.txt
>
>
> When you run logging into same file from many threads on a system that has more than one physical processor (Dual Core for example), a deadlock will occur after a while. This can not be reproduced on HyperThreading processors. Here's an example program that will demonstrate the behavior:
> -----------------------------
> Main.java
> -----------------------------
> import java.util.Date;
> import java.util.concurrent.ScheduledThreadPoolExecutor;
> import java.util.concurrent.TimeUnit;
> import org.slf4j.Logger;
> import org.slf4j.LoggerFactory;
> import ch.qos.logback.classic.LoggerContext;
> import ch.qos.logback.classic.joran.JoranConfigurator;
> import ch.qos.logback.core.joran.spi.JoranException;
> public class Main extends Thread
> {
>     private final static String LOGGER_CONFIGURATION_FILE = "logger.xml";
>     private final Logger logger = LoggerFactory.getLogger(Main.class);
>     
>     private final long start;
>     
>     public Main()
>         throws JoranException
>     {
>         start = new Date().getTime();
>         LoggerContext lc = (LoggerContext)LoggerFactory.getILoggerFactory();
>         JoranConfigurator configurator = new JoranConfigurator();
>         lc.shutdownAndReset();
>         configurator.setContext(lc);
>         configurator.doConfigure(LOGGER_CONFIGURATION_FILE);
>     }
>     
>     public void start()
>     {
>         ScheduledThreadPoolExecutor ex1 = new ScheduledThreadPoolExecutor(1);
>         ScheduledThreadPoolExecutor ex2 = new ScheduledThreadPoolExecutor(1);
>         ScheduledThreadPoolExecutor ex3 = new ScheduledThreadPoolExecutor(1);
>         ScheduledThreadPoolExecutor ex4 = new ScheduledThreadPoolExecutor(1);
>         ScheduledThreadPoolExecutor ex5 = new ScheduledThreadPoolExecutor(1);
>         ex1.scheduleAtFixedRate(new Task("EX1"), 10, 10, TimeUnit.MICROSECONDS);
>         ex2.scheduleAtFixedRate(new Task("EX2"), 10, 10, TimeUnit.MICROSECONDS);
>         ex3.scheduleAtFixedRate(new Task("EX3"), 10, 10, TimeUnit.MICROSECONDS);
>         ex4.scheduleAtFixedRate(new Task("EX4"), 10, 10, TimeUnit.MICROSECONDS);
>         ex5.scheduleAtFixedRate(new Task("EX5"), 10, 10, TimeUnit.MICROSECONDS);
>         
>         super.start();
>     }
>     
>     public void run()
>     {
>         try
>         {
>             while(true)
>             {
>                 logger.debug("[MAIN] {}", new Date().getTime() - start);
>                 Thread.sleep(10);
>             }
>         }
>         catch (InterruptedException e)
>         {
>             logger.info("[MAIN]: Interrupted: {}", e.getMessage());
>         }
>     }
>     
>     public static void main(String[] args)
>     {
>         try
>         {
>             Main main = new Main();
>             main.start();
>         }
>         catch (JoranException e)
>         {
>             System.out.println("Failed to load application: " + e.getMessage());
>         }
>     }
> }
> -------------------------------
> Task.java
> -------------------------------
> import java.util.Date;
> import org.slf4j.Logger;
> import org.slf4j.LoggerFactory;
> public class Task implements Runnable
> {
>     private final Logger logger = LoggerFactory.getLogger(Task.class);
>     private final Logger logger_main = LoggerFactory.getLogger(Main.class);
>     private final String name;
>     private final long start;
>     
>     public Task(final String name)
>     {
>         this.name = name;
>         start = new Date().getTime();
>     }
>     public void run()
>     {
>         logger.debug("[{}] {}", name, new Date().getTime() - start);
>         logger_main.debug("[MAIN] - [{}] {}", name, new Date().getTime() - start);
>     }
> }

-- 
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