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);
}
}
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 [EMAIL PROTECTED]
AppenderAttachable} interface.
+ * An implementation of the [EMAIL PROTECTED] 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;
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
