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... ]
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); } }
Index: logback-access/src/test/java/ch/qos/logback/access/jetty/JettyBasicTest.java =================================================================== --- logback-access/src/test/java/ch/qos/logback/access/jetty/JettyBasicTest.java (revision 1828) +++ logback-access/src/test/java/ch/qos/logback/access/jetty/JettyBasicTest.java (working copy) @@ -59,7 +59,7 @@ String result = Util.readToString(connection.getInputStream()); assertEquals("hello world", result); - //Thread.sleep(100); + Thread.sleep(100); ListAppender appender = (ListAppender) requestLogImpl.getAppender("list"); assertTrue(appender.list.size()>0); AccessEvent event = (AccessEvent) appender.list.get(0); Index: logback-classic/src/main/java/ch/qos/logback/classic/Logger.java =================================================================== --- logback-classic/src/main/java/ch/qos/logback/classic/Logger.java (revision 1828) +++ logback-classic/src/main/java/ch/qos/logback/classic/Logger.java (working copy) @@ -196,9 +196,7 @@ // propagate the parent levelInt change to this logger's children // propagate the parent levelInt change to this logger's children if (childrenList != null) { - int len = childrenList.size(); - for (int i = 0; i < len; i++) { - Logger child = (Logger) childrenList.get(i); + for (Logger child : childrenList) { child.handleParentLevelChange(newParentLevel); } } @@ -209,22 +207,24 @@ * Remove all previously added appenders from this logger instance. <p/> This * is useful when re-reading configuration information. */ - public synchronized void detachAndStopAllAppenders() { + public void detachAndStopAllAppenders() { if (aai != null) { aai.detachAndStopAllAppenders(); } } - public synchronized Appender<LoggingEvent> detachAppender(String name) { + public Appender<LoggingEvent> detachAppender(String name) { if (aai == null) { return null; } return aai.detachAppender(name); } - 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>(); + } } aai.addAppender(newAppender); } @@ -236,7 +236,7 @@ return aai.isAttached(appender); } - public synchronized Iterator iteratorForAppenders() { + public Iterator iteratorForAppenders() { if (aai == null) { return Collections.EMPTY_LIST.iterator(); } @@ -287,7 +287,7 @@ /** * Remove the appender passed as parameter form the list of appenders. */ - public synchronized boolean detachAppender(Appender appender) { + public boolean detachAppender(Appender appender) { if (aai == null) { return false; } Index: logback-core/src/test/java/ch/qos/logback/core/AllCoreTest.java =================================================================== --- logback-core/src/test/java/ch/qos/logback/core/AllCoreTest.java (revision 1828) +++ logback-core/src/test/java/ch/qos/logback/core/AllCoreTest.java (working copy) @@ -23,6 +23,7 @@ suite.addTest(ch.qos.logback.core.joran.PackageTest.suite()); suite.addTest(ch.qos.logback.core.appender.PackageTest.suite()); suite.addTest(ch.qos.logback.core.rolling.PackageTest.suite()); + suite.addTest(ch.qos.logback.core.spi.PackageTest.suite()); return suite; } } Index: logback-core/src/test/java/ch/qos/logback/core/spi/AppenderAttachableImplTest.java =================================================================== --- logback-core/src/test/java/ch/qos/logback/core/spi/AppenderAttachableImplTest.java (revision 0) +++ logback-core/src/test/java/ch/qos/logback/core/spi/AppenderAttachableImplTest.java (revision 0) @@ -0,0 +1,185 @@ +package ch.qos.logback.core.spi; + +import junit.framework.TestCase; +import junit.framework.Test; +import junit.framework.TestSuite; +import ch.qos.logback.core.ConsoleAppender; +import ch.qos.logback.core.AppenderBase; +import ch.qos.logback.core.Appender; +import ch.qos.logback.core.appender.NOPAppender; +import ch.qos.logback.core.layout.NopLayout; + +import java.util.Iterator; + +/** + * This test case verifies all the methods of AppenderAttableImpl work properly. + * + * @author Ceki + */ +public class AppenderAttachableImplTest extends TestCase { + /** + * To run test suite from command line. + */ + public static void main(String[] args) { + junit.textui.TestRunner.run(suite()); + } + + /** + * Set up a test suite. + */ + public static Test suite() { + return new TestSuite(AppenderAttachableImplTest.class); + } + + public AppenderAttachableImplTest(String testName) { + super(testName); + } + + private AppenderAttachableImpl at; + + protected void setUp() throws Exception { + super.setUp(); + at = new AppenderAttachableImpl(); + } + + protected void tearDown() throws Exception { + super.tearDown(); + at = null; + } + + public void testAddAppender() throws Exception { + TestEvent event = new TestEvent(); + TestAppender<TestEvent> ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.start(); + at.addAppender(ta); + ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.setName("test"); + ta.start(); + at.addAppender(ta); + int size = at.appendLoopOnAppenders(event); + assertTrue("Incorrect number of appenders", size == 2); + } + + public void testIteratorForAppenders() throws Exception { + TestAppender<TestEvent> ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.start(); + at.addAppender(ta); + TestAppender<TestEvent> tab = new TestAppender<TestEvent>(); + tab.setLayout(new NopLayout<TestEvent>()); + tab.setName("test"); + tab.start(); + at.addAppender(tab); + Iterator<TestAppender<TestEvent>> iter = at.iteratorForAppenders(); + int size = 0; + while (iter.hasNext()) { + ++size; + TestAppender<TestEvent> app = iter.next(); + assertTrue("Bad Appender", app == ta || app == tab); + } + assertTrue("Incorrect number of appenders", size == 2); + } + + public void getGetAppender() throws Exception { + TestAppender<TestEvent> ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.start(); + at.addAppender(ta); + ta.setName("test1"); + TestAppender<TestEvent> tab = new TestAppender<TestEvent>(); + tab.setLayout(new NopLayout<TestEvent>()); + tab.setName("test"); + tab.start(); + at.addAppender(tab); + Appender a = at.getAppender("test"); + assertNotNull("Could not find appender", a); + assertTrue("Wrong appender", a == tab); + a = at.getAppender("test1"); + assertNotNull("Could not find appender", a); + assertTrue("Wrong appender", a == ta); + a = at.getAppender("NotThere"); + assertNull("Appender was returned", a); + } + + public void testIsAttached() throws Exception { + TestAppender<TestEvent> ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.start(); + at.addAppender(ta); + ta.setName("test1"); + TestAppender<TestEvent> tab = new TestAppender<TestEvent>(); + tab.setLayout(new NopLayout<TestEvent>()); + tab.setName("test"); + tab.start(); + at.addAppender(tab); + assertTrue("Appender is not attached", at.isAttached(ta)); + assertTrue("Appender is not attached", at.isAttached(tab)); + } + + public void testDetachAndStopAllAppenders() throws Exception { + TestAppender<TestEvent> ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.start(); + at.addAppender(ta); + ta.setName("test1"); + TestAppender<TestEvent> tab = new TestAppender<TestEvent>(); + tab.setLayout(new NopLayout<TestEvent>()); + tab.setName("test"); + tab.start(); + at.addAppender(tab); + assertTrue("Appender was not started", tab.isStarted()); + at.detachAndStopAllAppenders(); + assertNull("Appender was not removed", at.getAppender("test")); + assertFalse("Appender was not stopped", tab.isStarted()); + } + + public void testDetachAppender() throws Exception { + TestAppender<TestEvent> ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.start(); + at.addAppender(ta); + ta.setName("test1"); + TestAppender<TestEvent> tab = new TestAppender<TestEvent>(); + tab.setLayout(new NopLayout<TestEvent>()); + tab.setName("test"); + tab.start(); + at.addAppender(tab); + assertTrue("Appender not detached", at.detachAppender(tab)); + assertNull("Appender was not removed", at.getAppender("test")); + assertFalse("Appender detach error", at.detachAppender(tab)); + } + + public void testDetachAppenderByName() throws Exception { + TestAppender<TestEvent> ta = new TestAppender<TestEvent>(); + ta.setLayout(new NopLayout<TestEvent>()); + ta.start(); + at.addAppender(ta); + ta.setName("test1"); + TestAppender<TestEvent> tab = new TestAppender<TestEvent>(); + tab.setLayout(new NopLayout<TestEvent>()); + tab.setName("test"); + tab.start(); + at.addAppender(tab); + Appender a = at.detachAppender("test"); + assertNotNull("Appender not detached", a); + a = at.detachAppender("test1"); + assertNotNull("Appender not detached", a); + a = at.detachAppender("test1"); + assertNull("Appender detach error", a); + } + + private static class TestEvent { + + } + + + private static class TestAppender<TestEvent> extends AppenderBase<TestEvent> { + + protected void append(TestEvent event) { + + } + + } +} \ No newline at end of file Index: logback-core/src/test/java/ch/qos/logback/core/spi/PackageTest.java =================================================================== --- logback-core/src/test/java/ch/qos/logback/core/spi/PackageTest.java (revision 0) +++ logback-core/src/test/java/ch/qos/logback/core/spi/PackageTest.java (revision 0) @@ -0,0 +1,15 @@ +package ch.qos.logback.core.spi; + +import junit.framework.TestCase; +import junit.framework.Test; +import junit.framework.TestSuite; + + +public class PackageTest extends TestCase { + + public static Test suite() { + TestSuite suite = new TestSuite(); + suite.addTestSuite(AppenderAttachableImplTest.class); + return suite; + } +} Index: logback-core/src/main/java/ch/qos/logback/core/spi/AppenderAttachableImpl.java =================================================================== --- logback-core/src/main/java/ch/qos/logback/core/spi/AppenderAttachableImpl.java (revision 1828) +++ logback-core/src/main/java/ch/qos/logback/core/spi/AppenderAttachableImpl.java (working copy) @@ -9,20 +9,29 @@ */ package ch.qos.logback.core.spi; -import java.util.ArrayList; import java.util.Iterator; -import java.util.List; +import java.util.Collection; +import java.util.Map; +import java.util.concurrent.ConcurrentMap; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicLong; import ch.qos.logback.core.Appender; /** - * A straightforward implementation of the {@link AppenderAttachable} interface. + * An implementation of the {@link AppenderAttachable} interface. This implementation would be + * much simpler if the name attribute of the Appender interface was required and was immutable. + * Since the name is not required to be set and might be changed or set after attaching it, this + * class must account for those rare occurances. * * @author Ceki Gülcü */ public class AppenderAttachableImpl<E> implements AppenderAttachable<E> { - final private List<Appender<E>> appenderList = new ArrayList<Appender<E>>(); + private final ConcurrentMap<String, Appender<E>> appenders = + new ConcurrentHashMap<String, Appender<E>>(); + private AtomicLong counter = new AtomicLong(); + private static final String APPENDER_NAME_ROOT = "__APPENDER__:"; /** * Attach an appender. If the appender is already in the list in won't be @@ -33,21 +42,21 @@ if (newAppender == null) { throw new IllegalArgumentException("Cannot null as an appener"); } - if (!appenderList.contains(newAppender)) { - appenderList.add(newAppender); + String name = newAppender.getName(); + if (name == null) + { + name = APPENDER_NAME_ROOT + counter.getAndIncrement(); } + appenders.putIfAbsent(name, newAppender); } /** * Call the <code>doAppend</code> method on all attached appenders. */ public int appendLoopOnAppenders(E e) { - int size = 0; - Appender<E> appender; - - size = appenderList.size(); - for (int i = 0; i < size; i++) { - appender = (Appender<E>) appenderList.get(i); + Collection<Appender<E>> coll = appenders.values(); + int size = coll.size(); + for (Appender appender : coll) { appender.doAppend(e); } return size; @@ -60,7 +69,7 @@ * @return Enumeration An enumeration of attached appenders. */ public Iterator iteratorForAppenders() { - return appenderList.iterator(); + return appenders.values().iterator(); } /** @@ -74,15 +83,13 @@ if (name == null) { return null; } - - int size = appenderList.size(); - Appender<E> appender; - - for (int i = 0; i < size; i++) { - appender = appenderList.get(i); - - if (name.equals(appender.getName())) { - return appender; + Appender<E> appender = appenders.get(name); + if (appender != null) { + return appender; + } + for (Appender<E> a : appenders.values()) { + if (name.equals(a.getName())) { + return a; } } @@ -100,17 +107,18 @@ return false; } - int size = appenderList.size(); - Appender a; - - for (int i = 0; i < size; i++) { - a = (Appender) appenderList.get(i); - + String name = appender.getName(); + if (name != null) { + Appender a = appenders.get(name); + if (a != null && a == appender) { + return true; + } + } + for (Appender a : appenders.values()) { if (a == appender) { return true; } } - return false; } @@ -118,14 +126,10 @@ * Remove and stop all previously attached appenders. */ public void detachAndStopAllAppenders() { - int len = appenderList.size(); - - for (int i = 0; i < len; i++) { - Appender a = (Appender) appenderList.get(i); - a.stop(); + for (Map.Entry<String, Appender<E>> entry : appenders.entrySet()) { + entry.getValue().stop(); + appenders.remove(entry.getKey(), entry.getValue()); } - - appenderList.clear(); } /** @@ -136,7 +140,16 @@ if (appender == null) { return false; } - return appenderList.remove(appender); + String name = appender.getName(); + if (appenders.containsKey(name)) { + return appenders.remove(name, appender); + } + for (Map.Entry<String, Appender<E>> entry : appenders.entrySet()) { + if (appender == entry.getValue()) { + return appenders.remove(entry.getKey(), appender); + } + } + return false; } /** @@ -147,12 +160,13 @@ if (name == null) { return null; } - - int size = appenderList.size(); - - for (int i = 0; i < size; i++) { - if (name.equals((appenderList.get(i)).getName())) { - return appenderList.remove(i); + Appender<E> a = appenders.remove(name); + if (a != null) { + return a; + } + for (Map.Entry<String, Appender<E>> entry : appenders.entrySet()) { + if (name.equals(entry.getValue().getName())) { + return appenders.remove(entry.getKey()); } } return null;