- logback-dev - mailman3.qos.ch

[JIRA] Issue Comment Edited: (LBCLASSIC-36) Synchronization of SimpleDateFormat object in DateConverter
by Ceki Gulcu (JIRA) 14 Jun '09

14 Jun '09

[ http://jira.qos.ch/browse/LBCLASSIC-36?page=com.atlassian.jira.plugin.syste… ] Ceki Gulcu edited comment on LBCLASSIC-36 at 6/14/09 9:28 PM: -------------------------------------------------------------- Thank you for this contribution. I have ran a modified (and simplified) version of your tests. It looks like SimpleDateFormat and Yoda time have roughly the same performance. with the former having the edge. Your version of the test had Yoda time transform Date objects. However, in logback, a "long" as obtained by System.currentMillis(), needs to be transformed. Transforming Date objects is pretty much beside the point. was (Author: noreply.ceki(a)qos.ch) Thank you for this patch. I have ran a modified (and simplified) version of your tests. It looks like SimpleDateFormat and Yoda time have roughly the same performance. with the former having the edge. > 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: Ceki Gulcu > Attachments: DateConverter_patch.java, dateformattest.zip > > > 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 Ceki Gulcu (JIRA) 14 Jun '09

14 Jun '09

[ http://jira.qos.ch/browse/LBCLASSIC-36?page=com.atlassian.jira.plugin.syste… ] Ceki Gulcu commented on LBCLASSIC-36: ------------------------------------- Thank you for this patch. I have ran a modified (and simplified) version of your tests. It looks like SimpleDateFormat and Yoda time have roughly the same performance. with the former having the edge. > 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: Ceki Gulcu > Attachments: DateConverter_patch.java, dateformattest.zip > > > 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

svn commit: r2290 - in logback/trunk/logback-classic: . src/test/java/ch/qos/logback/classic/issue/lbclassic36
by noreply.ceki＠qos.ch 14 Jun '09

14 Jun '09

Author: ceki Date: Sun Jun 14 21:22:00 2009 New Revision: 2290 Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/TestDateFormat.java Modified: logback/trunk/logback-classic/pom.xml Log: LBCLASSIC-36 Test performance of Yoda time compared to SimpleDateFormat. Here are sample results on my machine: Raw Joda: average tick 2714.052123 nanoseconds Sync SimpleDateFormat: average tick 2129.857639 nanoseconds Raw SimpleDateFormat: average tick 2138.306659 nanoseconds Conclusion: Yoda time and SimpleDataFormat have roughly equivalent performace, with the latter having the edge. Modified: logback/trunk/logback-classic/pom.xml ============================================================================== --- logback/trunk/logback-classic/pom.xml (original) +++ logback/trunk/logback-classic/pom.xml Sun Jun 14 21:22:00 2009 @@ -51,7 +51,7 @@ <version>${slf4j.version}</version> <scope>test</scope> </dependency> - + <dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> @@ -134,6 +134,13 @@ </exclusion> </exclusions> </dependency> + + <dependency> + <groupId>joda-time</groupId> + <artifactId>joda-time</artifactId> + <version>1.6</version> + <scope>test</scope> + </dependency> </dependencies> <build> @@ -151,10 +158,12 @@ <plugin> <groupId>org.apache.maven.plugins</groupId> <artifactId>maven-jar-plugin</artifactId> - <configuration> - <archive> - <manifestFile>${project.build.outputDirectory}/META-INF/MANIFEST.MF</manifestFile> - </archive> + <configuration> + <archive> + <manifestFile> + ${project.build.outputDirectory}/META-INF/MANIFEST.MF + </manifestFile> + </archive> </configuration> <executions> <execution> @@ -191,21 +200,23 @@ <execution> <id>bundle-manifest</id> <phase>process-classes</phase> - <goals> + <goals> <goal>manifest</goal> - </goals> + </goals> </execution> </executions> <configuration> <instructions> <Export-Package>ch.qos.logback.classic.*</Export-Package> <Export-Package>org.slf4j.impl;version=1.5.6</Export-Package> - <Import-Package>sun.reflect;resolution:=optional, - javax.jms;resolution:=optional, - * + <Import-Package> + sun.reflect;resolution:=optional, javax.jms;resolution:=optional, + * </Import-Package> - <Bundle-RequiredExecutionEnvironment>J2SE-1.5</Bundle-RequiredExecutionEnvironment> + <Bundle-RequiredExecutionEnvironment> + J2SE-1.5 + </Bundle-RequiredExecutionEnvironment> </instructions> </configuration> </plugin> Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/TestDateFormat.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/TestDateFormat.java Sun Jun 14 21:22:00 2009 @@ -0,0 +1,63 @@ +package ch.qos.logback.classic.issue.lbclassic36; + +import java.text.SimpleDateFormat; +import java.util.Date; + +import org.joda.time.format.DateTimeFormat; +import org.joda.time.format.DateTimeFormatter; + +public class TestDateFormat { + public static final String ISO8601_PATTERN = "yyyy-MM-dd HH:mm:ss,SSS"; + static final long NANOS_IN_ONE_SEC = 1000 * 1000 * 1000L; + + static long RUN_LENGTH = 1000*1000; + + public static void main(String[] args) { + for (int i = 0; i < 5; i++) { + doRawJoda(); + doRawSimpleDateFormat(); + doSyncronizedSimpleDateFormat(); + } + + print("Raw Joda: ", doRawJoda()); + print("Sync SimpleDateFormat: ", doSyncronizedSimpleDateFormat()); + print("Raw SimpleDateFormat: ", doRawSimpleDateFormat()); + } + + static void print(String msg, double avg) { + System.out.println(msg + " average tick " + avg + " nanoseconds"); + } + + static double doRawJoda() { + DateTimeFormatter jodaFormat = DateTimeFormat.forPattern(ISO8601_PATTERN); + long timeInMillis = new Date().getTime(); + long start = System.nanoTime(); + for (int i = 0; i < RUN_LENGTH; ++i) { + jodaFormat.print(timeInMillis); + } + return (System.nanoTime() - start) * 1.0d / RUN_LENGTH; + } + + static double doRawSimpleDateFormat() { + SimpleDateFormat simpleFormat = new SimpleDateFormat(ISO8601_PATTERN); + long timeInMillis = new Date().getTime(); + long start = System.nanoTime(); + for (int i = 0; i < RUN_LENGTH; ++i) { + simpleFormat.format(timeInMillis); + } + return (System.nanoTime() - start) * 1.0d / RUN_LENGTH; + } + + static double doSyncronizedSimpleDateFormat() { + SimpleDateFormat simpleFormat = new SimpleDateFormat(ISO8601_PATTERN); + long timeInMillis = new Date().getTime(); + long start = System.nanoTime(); + for (int i = 0; i < RUN_LENGTH; ++i) { + synchronized (simpleFormat) { + simpleFormat.format(timeInMillis); + } + } + return (System.nanoTime() - start) * 1.0d / RUN_LENGTH; + } + +}

1 0

[JIRA] Updated: (LBCLASSIC-36) Synchronization of SimpleDateFormat object in DateConverter
by Ralph Goers (JIRA) 14 Jun '09

14 Jun '09

[ http://jira.qos.ch/browse/LBCLASSIC-36?page=com.atlassian.jira.plugin.syste… ] Ralph Goers updated LBCLASSIC-36: --------------------------------- Attachment: dateformattest.zip Test to compare various ways of using SimpleDateFormat vs Joda Time. > 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: Ceki Gulcu > Attachments: DateConverter_patch.java, dateformattest.zip > > > 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 Ralph Goers (JIRA) 14 Jun '09

14 Jun '09

[ http://jira.qos.ch/browse/LBCLASSIC-36?page=com.atlassian.jira.plugin.syste… ] Ralph Goers commented on LBCLASSIC-36: -------------------------------------- Since you asked... I created a test to compare Joda Time to Simple Date Format. The results I get on my Mac are: Running TestDateFormat Raw - JDK: 3673 ns Joda: 2587 ns - Difference: 29.56711% Synchronized DateFormat: 0.4640 seconds Unsynchronized DateFormat: 2.2500 seconds ThreadLocal DateFormat: 0.2224 seconds Joda DateTimeFormatter: 0.1631 seconds Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 3.871 sec The raw test just performs a date format 100,000 times in a loop on a single thread. The synchronized test behaves like Logback currently does, synchronizing calls to format the date. The unsynchronized uses a new SimpleDateTime for each invocation. The threadlocal test creates a SimpleDateFormat for each thread. The joda test uses Joda Time's DateTimeFormatter. > 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: Ceki Gulcu > Attachments: DateConverter_patch.java, dateformattest.zip > > > 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

Throughput of fair locks
by Ceki Gulcu 13 Jun '09

13 Jun '09

Hello all, I added a new application measuring the compared throughtput of the synchronized primitive versus fair and unfair locks. Here are the results. java.runtime.version = 1.6.0_11-b03 java.vendor = Sun Microsystems Inc. java.version = 1.6.0_11 os.name = Linux os.version = 2.6.25-gentoo-r6 Sync: 139698775, or 35 nanos per cycle Unfair: 87028802, or 57 nanos per cycle Fair: 4106449, or 1217 nanos per cycle java.runtime.version = jvmxa6460-20081105_25433 java.vendor = IBM Corporation java.version = 1.6.0 os.name = Linux os.version = 2.6.25-gentoo-r6 Sync: 356946629, or 14 nanos per cycle Unfair: 91892449, or 54 nanos per cycle Fair: 7380308, or 677 nanos per cycle As you can see there is a substantial difference in throughput. The ration is about 40. Cheers, -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch

1 0

svn commit: r2289 - logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue
by noreply.ceki＠qos.ch 13 Jun '09

13 Jun '09

Author: ceki Date: Sat Jun 13 23:42:34 2009 New Revision: 2289 Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/NoLockingInJava.java (contents, props changed) Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockingInJava.java Log: - Measure performance when no locking is present. - We don't need to interrupt in LockingInJava Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockingInJava.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockingInJava.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockingInJava.java Sat Jun 13 23:42:34 2009 @@ -11,11 +11,12 @@ static int THREAD_COUNT = 5; static Object LOCK = new Object(); - static Runnable[] RUNNABLE_ARRAY = new Runnable[THREAD_COUNT]; + static LockingInJava[] RUNNABLE_ARRAY = new LockingInJava[THREAD_COUNT]; static Thread[] THREAD_ARRAY = new Thread[THREAD_COUNT]; private int counter = 0; - + private boolean done = false; + public static void main(String args[]) throws InterruptedException { printEnvironmentInfo(); execute(); @@ -47,9 +48,9 @@ Thread.sleep(10000); for (int i = THREAD_COUNT - 1; i <= 0; i--) { - THREAD_ARRAY[i].interrupt(); + RUNNABLE_ARRAY[i].done = true; } - Thread.sleep(100); // wait a moment for termination, to lazy for join ;) + } public static void printResults() { @@ -65,7 +66,9 @@ try { Thread.sleep(10); } catch (InterruptedException ex) { - break; + } + if(done) { + return; } } } Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/NoLockingInJava.java ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/NoLockingInJava.java Sat Jun 13 23:42:34 2009 @@ -0,0 +1,74 @@ +package ch.qos.logback.core.issue; + +/** + * Measure throughput without any locking policy + * + * @author Joern Huxhorn + * @author Ceki Gulcu + */ +public class NoLockingInJava implements Runnable { + + static int THREAD_COUNT = 5; + static Object LOCK = new Object(); + static NoLockingInJava[] RUNNABLE_ARRAY = new NoLockingInJava[THREAD_COUNT]; + static Thread[] THREAD_ARRAY = new Thread[THREAD_COUNT]; + + private int counter = 0; + private boolean done = false; + + public static void main(String args[]) throws InterruptedException { + printEnvironmentInfo(); + execute(); + printResults(); + } + + public static void printEnvironmentInfo() { + System.out.println("java.runtime.version = " + + System.getProperty("java.runtime.version")); + System.out.println("java.vendor = " + + System.getProperty("java.vendor")); + System.out.println("java.version = " + + System.getProperty("java.version")); + System.out.println("os.name = " + + System.getProperty("os.name")); + System.out.println("os.version = " + + System.getProperty("os.version")); + } + + public static void execute() throws InterruptedException { + for (int i = 0; i < THREAD_COUNT; i++) { + RUNNABLE_ARRAY[i] = new NoLockingInJava(); + THREAD_ARRAY[i] = new Thread(RUNNABLE_ARRAY[i]); + } + for (Thread t : THREAD_ARRAY) { + t.start(); + } + // let the threads run for a while + Thread.sleep(10000); + + for (int i = THREAD_COUNT - 1; i <= 0; i--) { + RUNNABLE_ARRAY[i].done = true; + } + + } + + public static void printResults() { + for (int i = 0; i < RUNNABLE_ARRAY.length; i++) { + System.out.println("runnable[" + i + "]: " + RUNNABLE_ARRAY[i]); + } + } + + public void run() { + for (;;) { + counter++; + if (done) { + return; + } + } + } + + public String toString() { + return "counter=" + counter; + } + +}

1 0

svn commit: r2288 - logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue
by noreply.ceki＠qos.ch 13 Jun '09

13 Jun '09

Author: ceki Date: Sat Jun 13 23:31:29 2009 New Revision: 2288 Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockThroughput.java (contents, props changed) Log: Code comparing the throughput of fair lock and that of sync blocks Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockThroughput.java ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockThroughput.java Sat Jun 13 23:31:29 2009 @@ -0,0 +1,141 @@ +package ch.qos.logback.core.issue; + +import java.util.concurrent.locks.Lock; +import java.util.concurrent.locks.ReentrantLock; + +/** + * Short sample code testing the throughput of a fair lock. + * + * @author Joern Huxhorn + * @author Ceki Gulcu + */ +public class LockThroughput implements Runnable { + + enum LockingModel { + SYNC, FAIR, UNFAIR; + } + + static int THREAD_COUNT = 2; + static long OVERALL_DURATION_IN_MILLIS = 5000; + static LockThroughput[] RUNNABLE_ARRAY = new LockThroughput[THREAD_COUNT]; + static Thread[] THREAD_ARRAY = new Thread[THREAD_COUNT]; + + static Object LOCK = new Object(); + static Lock FAIR_LOCK = new ReentrantLock(true); + static Lock UNFAIR_LOCK = new ReentrantLock(false); + + static private int COUNTER = 0; + + LockingModel model; + boolean done = false; + + public static void main(String args[]) throws InterruptedException { + printEnvironmentInfo(); + execute(LockingModel.SYNC); + execute(LockingModel.UNFAIR); + execute(LockingModel.FAIR); + + COUNTER = 0; + execute(LockingModel.SYNC); + cleanUpAndPrintResults("Sync: "); + execute(LockingModel.UNFAIR); + cleanUpAndPrintResults("Unfair: "); + execute(LockingModel.FAIR); + cleanUpAndPrintResults("Fair: "); + + } + + public static void printEnvironmentInfo() { + System.out.println("java.runtime.version = " + + System.getProperty("java.runtime.version")); + System.out.println("java.vendor = " + + System.getProperty("java.vendor")); + System.out.println("java.version = " + + System.getProperty("java.version")); + System.out.println("os.name = " + + System.getProperty("os.name")); + System.out.println("os.version = " + + System.getProperty("os.version")); + } + + public static void execute(LockingModel model) throws InterruptedException { + for (int i = 0; i < THREAD_COUNT; i++) { + RUNNABLE_ARRAY[i] = new LockThroughput(model); + THREAD_ARRAY[i] = new Thread(RUNNABLE_ARRAY[i]); + } + for (Thread t : THREAD_ARRAY) { + t.start(); + } + // let the threads run for a while + Thread.sleep(OVERALL_DURATION_IN_MILLIS); + + for (int i = 0; i < THREAD_COUNT; i++) { + RUNNABLE_ARRAY[i].done = true; + } + } + + public static void cleanUpAndPrintResults(String model) throws InterruptedException { + for (int i = 0; i < THREAD_COUNT; i++) { + THREAD_ARRAY[i].join(); + } + System.out.println(model + COUNTER+", or "+ ((OVERALL_DURATION_IN_MILLIS*1000*1000L)/COUNTER) +" nanos per cycle"); + COUNTER = 0; + } + + LockThroughput(LockingModel model) { + this.model = model; + } + + + void fairLockRun() { + for (;;) { + FAIR_LOCK.lock(); + COUNTER++; + FAIR_LOCK.unlock(); + if (done) { + return; + } + } + } + + void unfairLockRun() { + for (;;) { + UNFAIR_LOCK.lock(); + COUNTER++; + UNFAIR_LOCK.unlock(); + if (done) { + return; + } + } + } + + void synchronizedRUn() { + for (;;) { + synchronized (LOCK) { + COUNTER++; + if (done) { + return; + } + } + } + } + + public void run() { + switch (model) { + case SYNC: + synchronizedRUn(); + break; + case FAIR: + fairLockRun(); + break; + case UNFAIR: + unfairLockRun(); + break; + } + } + + public String toString() { + return "counter=" + COUNTER; + } + +}

1 0

svn commit: r2287 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133
by noreply.ceki＠qos.ch 13 Jun '09

13 Jun '09

Author: ceki Date: Sat Jun 13 17:34:06 2009 New Revision: 2287 Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/DeadlockTest.java Log: LBCLASSIC-133 We don't need to unit test test. A standalone app, is just as good if not simpler to run. Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/DeadlockTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/DeadlockTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/DeadlockTest.java Sat Jun 13 17:34:06 2009 @@ -2,28 +2,31 @@ import static org.junit.Assert.assertFalse; -import org.junit.Test; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class DeadlockTest { private static Logger s_logger = LoggerFactory.getLogger(DeadlockTest.class); - @Test - public void deadlockTest() throws Exception { + public static void main(String[] args) throws Exception { s_logger.debug("Starting test."); final Worker worker = new Worker(); final Thread workerThread = new Thread(new Runnable() { public void run() { - worker.work(); + while (true) { + worker.work(); + } } }); workerThread.setName("WorkerThread"); final Thread accessorThread = new Thread(new Runnable() { public void run() { - new Accessor().access(worker); + Accessor a = new Accessor(); + while (true) { + a.access(worker); + } } }); accessorThread.setName("AccessorThread"); @@ -31,7 +34,7 @@ workerThread.start(); accessorThread.start(); - workerThread.join(5 * 1000); + workerThread.join(50 * 1000); assertFalse("Worker thread seems locked.", workerThread.isAlive()); } }

1 0

svn commit: r2286 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133
by noreply.ceki＠qos.ch 13 Jun '09

13 Jun '09

Author: ceki Date: Sat Jun 13 17:16:07 2009 New Revision: 2286 Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/Accessor.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/DeadlockTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/Worker.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/logback-test.xml Log: files associated with LBCLASSIC-133 Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/Accessor.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/Accessor.java Sat Jun 13 17:16:07 2009 @@ -0,0 +1,23 @@ +package ch.qos.logback.classic.issue.lbclassic133; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +public class Accessor { + private static Logger s_logger = LoggerFactory.getLogger(Accessor.class); + + public void access(Worker worker) { + /** + * at some point, for any reason, this method decides to log the status of + * the worker object. + */ + s_logger.debug("Current worker status is: {}.", worker); + /** + * the following line would not cause the deadlock, because the thread never + * tries to acquire a lock on worker while already having a lock on the + * logger. + */ + //s_logger.debug("Current worker status (not deadlocking) is: {}.", worker + // .toString()); + } +} Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/DeadlockTest.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/DeadlockTest.java Sat Jun 13 17:16:07 2009 @@ -0,0 +1,37 @@ +package ch.qos.logback.classic.issue.lbclassic133; + +import static org.junit.Assert.assertFalse; + +import org.junit.Test; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +public class DeadlockTest { + private static Logger s_logger = LoggerFactory.getLogger(DeadlockTest.class); + + @Test + public void deadlockTest() throws Exception { + s_logger.debug("Starting test."); + + final Worker worker = new Worker(); + final Thread workerThread = new Thread(new Runnable() { + public void run() { + worker.work(); + } + }); + workerThread.setName("WorkerThread"); + + final Thread accessorThread = new Thread(new Runnable() { + public void run() { + new Accessor().access(worker); + } + }); + accessorThread.setName("AccessorThread"); + + workerThread.start(); + accessorThread.start(); + + workerThread.join(5 * 1000); + assertFalse("Worker thread seems locked.", workerThread.isAlive()); + } +} Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/Worker.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/Worker.java Sat Jun 13 17:16:07 2009 @@ -0,0 +1,40 @@ +package ch.qos.logback.classic.issue.lbclassic133; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +public class Worker { + private static Logger s_logger = LoggerFactory.getLogger(Worker.class); + + private final Object m_lock = new Object(); + + public void work() { + // Locks the object to do some work changing internal status. + synchronized (m_lock) { + // Does some work... + try { + Thread.sleep(1 * 1000); + } catch (InterruptedException exc) { + // + } + // Then calls logger, while still holding the lock. + s_logger.debug("Did some work, result is: {}."/* ,... */); + } + } + + public String getStatus() { + // Locks the object to make sure the status snapshot is coherent. (Will + // deadlock.) + synchronized (m_lock) { + // Packs some status information, e.g. in a StringBuffer. + final StringBuffer buf = new StringBuffer("STATUS"); + // Returns the string. + return buf.toString(); + } + } + + @Override + public String toString() { + return getStatus(); + } +} \ No newline at end of file Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/logback-test.xml ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic133/logback-test.xml Sat Jun 13 17:16:07 2009 @@ -0,0 +1,16 @@ +<?xml version="1.0" encoding="UTF-8"?> +<configuration> + + <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> + <layout class="ch.qos.logback.classic.PatternLayout"> + <param name="Pattern" + value="%relative %level [%thread] %logger{25} %message %nopex\n" /> + </layout> + </appender> + + <root> + <level value="DEBUG" /> + <appender-ref ref="STDOUT" /> + </root> + +</configuration> \ No newline at end of file

1 0