- logback-dev - mailman3.qos.ch

[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: (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] 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] 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

[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 12:26 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. 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 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

1 0

Appender synchronization
by Ralph Goers 11 Oct '08

11 Oct '08

I would have opened a Jira issue for this (I will) but it appears to be unavailable. We have run into a serious performance problem with a custom appender. The appender is not particularly fast and logback ends up being a system wide bottleneck. This is because the doAppend method of AppenderBase is synchronzed and Logger's callApenders method calls appendLoopOnAppenders within a synchronzed block. Synchronized blocks should always be as small as possible. Synchronizing appender calls is just asking for trouble. Chapter 4 currently documents this behavior and should be changed. In my case I can avoid the first issue by having my appender override doAppend, but this really shouldn't be necessary. It would be much better to have appenders that aren't thread safe synchronize on the doAppend method or, better yet, within the method. The guard to avoid recursion can be handled with a thread local. As for callAppenders, there is unfortunately no way for me to bypass this problem without patching logback. java.util.concurrent provides several ways to avoid this. One would be to replace the synchronization with a ReadWriteLock. An even better alternative would be to completely remove the synchronization from Logger and change AppenderAttachableImpl use a ReadWriteLock to manage access to the appender List. I will try to work up some patches for these and add them to jira when they are done and jira is available again. Ralph

1 0

svn commit: r1828 - logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling
by noreply.ceki＠qos.ch 08 Oct '08

08 Oct '08

Author: ceki Date: Wed Oct 8 23:06:07 2008 New Revision: 1828 Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java Log: - renamed FileAppender.setFile method as openFile Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/rolling/RollingFileAppender.java Wed Oct 8 23:06:07 2008 @@ -98,7 +98,7 @@ try { // This will also close the file. This is OK since multiple // close operations are safe. - this.setFile(); + this.openFile(); } catch (IOException e) { addError( "setFile(" + fileName + ", false) call failed.", e);

1 0

[JIRA] Resolved: (LBCORE-42) add option to FileAppender to auto-create parent directories
by Ceki Gulcu (JIRA) 08 Oct '08

08 Oct '08

[ http://jira.qos.ch/browse/LBCORE-42?page=com.atlassian.jira.plugin.system.i… ] Ceki Gulcu resolved LBCORE-42. ------------------------------ Fix Version/s: 0.9.10 Resolution: Fixed Fixed > add option to FileAppender to auto-create parent directories > ------------------------------------------------------------ > > Key: LBCORE-42 > URL: http://jira.qos.ch/browse/LBCORE-42 > Project: logback-core > Issue Type: Bug > Components: Appender > Affects Versions: unspecified > Environment: Operating System: Linux > Platform: PC > Reporter: Bruno Navert > Assignee: Logback dev list > Fix For: 0.9.10 > > Attachments: FileAppender.java.patch > > > FileAppender should be able to automatically create parent directories as needed when writing the log file. > For instance, if configured with <File>/var/tmp/project_name/some_file.log</File>, and the new option set to true (suggest <CreateParentDirectories>true</CreateParentDirectories> maybe), then in FileAppender.setFile(), it should do > new File( fileName ).getParentFile().mkdirs() > workaround is to create the directory before initializing logback. Possible but far less than ideal, and rather complicated too -- 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