[prev in list] [next in list] [prev in thread] [next in thread] 

List:       logback-dev
Subject:    [logback-dev] [JIRA] Commented: (LBCLASSIC-35) Deadlock when
From:       "Ceki Gulcu (JIRA)" <noreply-jira () qos ! ch>
Date:       2008-09-23 10:35:50
Message-ID: 939582406.1222166150077.JavaMail.ceki () pixie
[Download RAW message or body]


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

Ceki Gulcu commented on LBCLASSIC-35:
-------------------------------------

As Earwin observes, there is no deadlock. However, it is true that there is \
contention on the same resource, that is the logger with appenders attached, in this \
case, the root logger. Thus, during logging all threads a synchronized on the root \
logger, see Logger.callAppenders(Logger.java:265). We could loosen this particular \
synchronization by using read-locks allowing concurrent access to the root logger. \
However, this would displace the contention point to appenders which can process only \
one event at a time. (The doAppend method in method AppenderBase is synchronized.)

I think the slowness observed is caused by the Console plug-in which grinds to a \
near-halt after 5 minutes of intensive use by the "Main" application above. If you \
restart Main, then the laggard behavior is observed almost immediately, which leads \
me to think that the problem is with the Console plug-in. My suspicion can be \
confirmed by commenting out <consolePlugin /> in the configuration file because \
thereafter the problem can no longer observed.

I am leaving this bug open so that we can come back to it to fix the Console plug-in. \
If you think that there is a dead-lock or a contention issues in logback, then I \
invite you to open a new issue.


> 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);
> }
> }

-- 
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@qos.ch
http://qos.ch/mailman/listinfo/logback-dev


[prev in list] [next in list] [prev in thread] [next in thread]