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

[Ralph Goers]

I'm attaching the patch for LBCLASSIC-35 to this email since I 
apparently don't have permission to add it to the Jira.

Ralph Goers (JIRA) wrote:
>     [ http://jira.qos.ch/browse/LBCLASSIC-35?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=10750#action_10750 ] 
>
> Ralph Goers commented on LBCLASSIC-35:
> --------------------------------------
>
> This bug needs to be fixed as does the bug in AppenderBase. I have attached the fix for this issue and will open a second issue for AppenderBase.
>
> FWIW, in some cases slow appenders wouldn't be as much of a problem if it weren't for these synchronization points. I have a custom appender that is slow, but is thread safe so many of them can be run in parallel. With these two synchronization points however, Logback ends up showing up as a system wide bottleneck.
>
>   
>> 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
>>
>> 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);
>>     }
>> }
>>     
>
>   
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: patch.txt
Url: http://qos.ch/pipermail/logback-dev/attachments/20081012/338eb5a8/attachment-0001.txt