October 2008 - logback-dev - mailman3.qos.ch

[JIRA] Commented: (LBCLASSIC-35) Deadlock when running on multiple core processors
by Dummy Tester (JIRA) 14 Oct '08

14 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-35?page=com.atlassian.jira.plugin.syste… ] Dummy Tester commented on LBCLASSIC-35: --------------------------------------- Ralph, If it will make the code simpler, I have no qualms with making appender names non-mutable. Moreover, we can further impose that loggers only accept named appenders rejecting anonymous one. I see that you have displaced the synchronization blocks from Logger to AppenderAttachableImpl, which seems quite reasonable to me. However, and if I am reading the patch correctly, you have not removed the synchronization from callAppender (line 265). The code still reads public void callAppenders(LoggingEvent event) { int writes = 0; // System.out.println("callAppenders"); for (Logger l = this; l != null; l = l.parent) { // System.out.println("l="+l.getName()); // Protected against simultaneous call to addAppender, removeAppender,... synchronized (l) { <--- this is what I am takling about writes += l.appendLoopOnAppenders(event); if (!l.additive) { break; } } } You have also kept a synchronization point in addAppender - 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>(); + } } So I don't see any gain with respect to the existing code. What am I missing? Having said that, I do not wish to offhandedly discard your contribution. I was thinking that given that the 'aai' variable is assigned only once (and never set to null again), it would be possible to remove both remaining synchronization points. This would completely get rid of synchronization on "this" (the Logger instance) with synchronization point moved into ApppenderAttachableImpl, which frankly does not seem to be much of a gain to be worth the trouble. Would you concur with my analysis? > 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 > Attachments: patch.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

1 0

svn commit: r1829 - logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic
by noreply.ceki＠qos.ch 14 Oct '08

14 Oct '08

Author: ceki Date: Tue Oct 14 19:32:04 2008 New Revision: 1829 Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/Logger.java Log: removed duplicate line (without changing the total number of lines) Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/Logger.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/Logger.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/Logger.java Tue Oct 14 19:32:04 2008 @@ -193,7 +193,7 @@ if (level == null) { effectiveLevelInt = newParentLevel.levelInt; - // 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();

1 0

[JIRA] Commented: (LBCLASSIC-36) Synchronization of SimpleDateFormat object in DateConverter
by Ralph Goers (JIRA) 13 Oct '08

13 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-36?page=com.atlassian.jira.plugin.syste… ] Ralph Goers commented on LBCLASSIC-36: -------------------------------------- This issue should be reopened. First, synchronization on the doAppend method of AppenderBase is a bug that needs to be corrected as documented in LBCORE-58. Secondly, SimpleDateFormat is horribly slow. The DateConverters should be modified to use Joda Time instead of the JDK Date and Time handling. Joda Time is both thread safe and fast. In addition, the Joda Time constructs will be brought in to Java 7 so this will provide an easy migration when that JDK becomes the baseline. In addition to the DateConverters, SyslogStartConverter also needs to be modified. > Synchronization of SimpleDateFormat object in DateConverter > ----------------------------------------------------------- > > Key: LBCLASSIC-36 > URL: http://jira.qos.ch/browse/LBCLASSIC-36 > Project: logback-classic > Issue Type: Bug > Components: Other > Affects Versions: unspecified > Environment: Operating System: All > Platform: All > Reporter: Anders Hammar > Assignee: Logback dev list > Attachments: DateConverter_patch.java > > > According to the API documentation of SimpleDateFormat, date formats are not synchronized and it is recommended to create separate format instances for each thread. > However, a possibly simpler (mer efficient) solution would be to synchronize on the SimpleDateFormat object in the convert() method to prevent two threads to access it concurrently. -- 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

1 0

[JIRA] Updated: (LBCLASSIC-36) Synchronization of SimpleDateFormat object in DateConverter
by Dummy Tester (JIRA) 13 Oct '08

13 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-36?page=com.atlassian.jira.plugin.syste… ] Dummy Tester updated LBCLASSIC-36: ---------------------------------- Comment: was deleted > Synchronization of SimpleDateFormat object in DateConverter > ----------------------------------------------------------- > > Key: LBCLASSIC-36 > URL: http://jira.qos.ch/browse/LBCLASSIC-36 > Project: logback-classic > Issue Type: Bug > Components: Other > Affects Versions: unspecified > Environment: Operating System: All > Platform: All > Reporter: Anders Hammar > Assignee: Logback dev list > Attachments: DateConverter_patch.java > > > According to the API documentation of SimpleDateFormat, date formats are not synchronized and it is recommended to create separate format instances for each thread. > However, a possibly simpler (mer efficient) solution would be to synchronize on the SimpleDateFormat object in the convert() method to prevent two threads to access it concurrently. -- 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

1 0

[JIRA] Commented: (LBCLASSIC-36) Synchronization of SimpleDateFormat object in DateConverter
by Dummy Tester (JIRA) 13 Oct '08

13 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-36?page=com.atlassian.jira.plugin.syste… ] Dummy Tester commented on LBCLASSIC-36: --------------------------------------- testing > Synchronization of SimpleDateFormat object in DateConverter > ----------------------------------------------------------- > > Key: LBCLASSIC-36 > URL: http://jira.qos.ch/browse/LBCLASSIC-36 > Project: logback-classic > Issue Type: Bug > Components: Other > Affects Versions: unspecified > Environment: Operating System: All > Platform: All > Reporter: Anders Hammar > Assignee: Logback dev list > Attachments: DateConverter_patch.java > > > According to the API documentation of SimpleDateFormat, date formats are not synchronized and it is recommended to create separate format instances for each thread. > However, a possibly simpler (mer efficient) solution would be to synchronize on the SimpleDateFormat object in the convert() method to prevent two threads to access it concurrently. -- 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

1 0

[JIRA] Updated: (LBCLASSIC-35) Deadlock when running on multiple core processors
by Ceki Gulcu (JIRA) 13 Oct '08

13 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-35?page=com.atlassian.jira.plugin.syste… ] Ceki Gulcu updated LBCLASSIC-35: -------------------------------- Attachment: patch.txt Patch posted by Raph http://www.qos.ch/pipermail/logback-dev/2008-October/002866.html http://qos.ch/pipermail/logback-dev/attachments/20081012/338eb5a8/attachmen… > 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 > Attachments: patch.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

1 0

[JIRA] Updated: (LBCLASSIC-35) Deadlock when running on multiple core processors
by Ceki Gulcu (JIRA) 13 Oct '08

13 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-35?page=com.atlassian.jira.plugin.syste… ] Ceki Gulcu updated LBCLASSIC-35: -------------------------------- Attachment: (was: date.txt) > 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 > Attachments: patch.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

1 0

[JIRA] Commented: (LBCLASSIC-35) Deadlock when running on multiple core processors
by Ralph Goers (JIRA) 13 Oct '08

13 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-35?page=com.atlassian.jira.plugin.syste… ] 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); > } > } -- 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

3 2

[JIRA] Updated: (LBCLASSIC-35) Deadlock when running on multiple core processors
by Ceki Gulcu (JIRA) 13 Oct '08

13 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-35?page=com.atlassian.jira.plugin.syste… ] Ceki Gulcu updated LBCLASSIC-35: -------------------------------- Attachment: date.txt Testing attachments > 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 > Attachments: date.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

1 0

[JIRA] Issue Comment Edited: (LBCLASSIC-35) Deadlock when running on multiple core processors
by Ralph Goers (JIRA) 12 Oct '08

12 Oct '08

[ http://jira.qos.ch/browse/LBCLASSIC-35?page=com.atlassian.jira.plugin.syste… ] Ralph Goers edited comment on LBCLASSIC-35 at 10/13/08 1:02 AM: ---------------------------------------------------------------- This bug needs to be fixed as does the bug in AppenderBase. I have a patch that fixes this issue but I don't seem to have permission to attach it to this issue. I have sent the patch to the dev list. I would appreciate it if someone with permission could attach it to this issue for me. 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. was (Author: rgoers(a)apache.org) This bug needs to be fixed as does the bug in AppenderBase. I have a patch that fixes this issue but I don't seem to have permission to attach it to this issue. 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); > } > } -- 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

1 0