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

[Robert Dale (JIRA)]

    [ http://jira.qos.ch/browse/LBCORE-63?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11093#action_11093 ] 

Robert Dale commented on LBCORE-63:
-----------------------------------

Any progress on this issue?  I'm getting:

   java.lang.Thread.State: BLOCKED on ch.qos.logback.core.rolling.RollingFileAppender at 2db3f4 owned by: http-127.0.0.1-8080-2
        at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:393)
        at ch.qos.logback.classic.Logger.debug(Logger.java:500)

Thanks.

> Deadlock when running on multiple core processors
> -------------------------------------------------
>
>                 Key: LBCORE-63
>                 URL: http://jira.qos.ch/browse/LBCORE-63
>             Project: logback-core
>          Issue Type: Sub-task
>    Affects Versions: 0.9.9
>         Environment: Operating System: Windows
> Platform: PC
>            Reporter: Toni Heimala
>            Assignee: Ceki Gulcu
>            Priority: Blocker
>         Attachments: patch.txt, patch2.txt, patch3.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