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

[Dummy Tester (JIRA)]

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

Dummy Tester commented on LBCLASSIC-35:
---------------------------------------

Ralph,

If it will make the code simpler, I have no qualms with making
appender names non-mutable. Moreover, we can further impose that
loggers only accept named appenders rejecting anonymous one.

I see that you have displaced the synchronization blocks from Logger to
AppenderAttachableImpl, which seems quite reasonable to me. However,
and if I am reading the patch correctly, you have not removed the
synchronization from callAppender (line 265). The code still reads

  public void callAppenders(LoggingEvent event) {
    int writes = 0;
    // System.out.println("callAppenders");
    for (Logger l = this; l != null; l = l.parent) {
      // System.out.println("l="+l.getName());
      // Protected against simultaneous call to addAppender, removeAppender,...
      synchronized (l) { <--- this is what I am takling about
        writes += l.appendLoopOnAppenders(event);
        if (!l.additive) {
          break;
        }
      }
    }


You have also kept a synchronization point in addAppender

-  public synchronized void addAppender(Appender<LoggingEvent> newAppender) {
-    if (aai == null) {
-      aai = new AppenderAttachableImpl<LoggingEvent>();
+  public void addAppender(Appender<LoggingEvent> newAppender) {
+    synchronized(this) {
+        if (aai == null) {
+            aai = new AppenderAttachableImpl<LoggingEvent>();
+        }
     }

So I don't see any gain with respect to the existing code. What am I
missing?

Having said that, I do not wish to offhandedly discard your contribution. I was 
thinking that given that the 'aai' variable is assigned only once (and never set to 
null again), it would be possible to remove both remaining synchronization points. 
This would completely get rid of synchronization on "this" (the Logger instance) 
with synchronization point moved into ApppenderAttachableImpl, which frankly 
does not seem to be much of a gain to be worth the trouble. Would you concur with
my analysis?


> 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