Author: ceki Date: Mon Jun 15 20:55:01 2009 New Revision: 2293 Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/DateFormattingThreadedThroughputCalculator.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/SelectiveDateFormattingRunnable.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/RunnableForThrougputComputation.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/SelectiveLockRunnable.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/ThreadedThroughputCalculator.java Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/DateFormatPerfTest.java logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockThroughput.java Log: Added ThreadedThroughputCalculator which is a scaffolding class to perform threaded computations. This commit is related to LBCLASSIC-36 as well as LBCORE-97 Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/DateFormatPerfTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/DateFormatPerfTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/DateFormatPerfTest.java Mon Jun 15 20:55:01 2009 @@ -16,15 +16,10 @@ for (int i = 0; i < 5; i++) { doRawJoda(); doRawSDF(); - doGuardedJoda(); - doGuardedSDF(); } print("Raw Joda: ", doRawJoda()); print("Raw SDF: ", doRawSDF()); - print("Guarded Joda: ", doGuardedJoda()); - print("Guarded SDF: ", doGuardedSDF()); - } static void print(String msg, double avg) { @@ -41,22 +36,6 @@ return (System.nanoTime() - start) * 1.0d / RUN_LENGTH; } - static double doGuardedJoda() { - DateTimeFormatter jodaFormat = DateTimeFormat.forPattern(ISO8601_PATTERN); - long start = System.nanoTime(); - long cache = 0; - for (int i = 0; i < RUN_LENGTH; ++i) { - synchronized (jodaFormat) { - long now = System.currentTimeMillis(); - if (cache != now) { - cache = now; - jodaFormat.print(now); - } - } - } - return (System.nanoTime() - start) * 1.0d / RUN_LENGTH; - } - static double doRawSDF() { SimpleDateFormat simpleFormat = new SimpleDateFormat(ISO8601_PATTERN); long timeInMillis = new Date().getTime(); @@ -67,19 +46,4 @@ return (System.nanoTime() - start) * 1.0d / RUN_LENGTH; } - static double doGuardedSDF() { - SimpleDateFormat simpleFormat = new SimpleDateFormat(ISO8601_PATTERN); - long start = System.nanoTime(); - long cache = 0; - for (int i = 0; i < RUN_LENGTH; ++i) { - synchronized (simpleFormat) { - long now = System.currentTimeMillis(); - if (cache != now) { - cache = now; - simpleFormat.format(now); - } - } - } - return (System.nanoTime() - start) * 1.0d / RUN_LENGTH; - } } Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/DateFormattingThreadedThroughputCalculator.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/DateFormattingThreadedThroughputCalculator.java Mon Jun 15 20:55:01 2009 @@ -0,0 +1,45 @@ +package ch.qos.logback.classic.issue.lbclassic36; + +import ch.qos.logback.classic.issue.lbclassic36.SelectiveDateFormattingRunnable.FormattingModel; +import ch.qos.logback.core.issue.ThreadedThroughputCalculator; + +/** + * Measure the threaded throughtput of date formatting operations + * + * @author Joern Huxhorn + * @author Ceki Gulcu + */ +public class DateFormattingThreadedThroughputCalculator { + + static int THREAD_COUNT = 16; + static long OVERALL_DURATION_IN_MILLIS = 3000; + + public static void main(String args[]) throws InterruptedException { + + ThreadedThroughputCalculator tp = new ThreadedThroughputCalculator( + OVERALL_DURATION_IN_MILLIS); + tp.printEnvironmentInfo("DateFormatting"); + + for (int i = 0; i < 2; i++) { + tp.execute(buildArray(FormattingModel.SDF)); + tp.execute(buildArray(FormattingModel.JODA)); + } + + tp.execute(buildArray(FormattingModel.JODA)); + tp.printThroughput("JODA: "); + + tp.execute(buildArray(FormattingModel.SDF)); + tp.printThroughput("SDF: "); + + + } + + static SelectiveDateFormattingRunnable[] buildArray(FormattingModel model) { + SelectiveDateFormattingRunnable[] array = new SelectiveDateFormattingRunnable[THREAD_COUNT]; + for (int i = 0; i < THREAD_COUNT; i++) { + array[i] = new SelectiveDateFormattingRunnable(model); + } + return array; + } + +} Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/SelectiveDateFormattingRunnable.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/issue/lbclassic36/SelectiveDateFormattingRunnable.java Mon Jun 15 20:55:01 2009 @@ -0,0 +1,86 @@ +package ch.qos.logback.classic.issue.lbclassic36; + +import java.text.SimpleDateFormat; +import org.joda.time.format.DateTimeFormat; +import org.joda.time.format.DateTimeFormatter; + +import ch.qos.logback.core.issue.RunnableForThrougputComputation; + +/** + * A runnable which behaves differently depending on the desired locking model. + * + * @author Raplh Goers + * @author Ceki Gulcu + */ +public class SelectiveDateFormattingRunnable extends + RunnableForThrougputComputation { + + public static final String ISO8601_PATTERN = "yyyy-MM-dd HH:mm:ss,SSS"; + + enum FormattingModel { + SDF, JODA; + } + + FormattingModel model; + static long CACHE = 0; + + static SimpleDateFormat SDF = new SimpleDateFormat(ISO8601_PATTERN); + static final DateTimeFormatter JODA = DateTimeFormat + .forPattern(ISO8601_PATTERN); + + SelectiveDateFormattingRunnable(FormattingModel model) { + this.model = model; + } + + public void run() { + switch (model) { + case SDF: + sdfRun(); + break; + case JODA: + jodaRun(); + break; + } + } + + void sdfRun() { + + for (;;) { + synchronized (SDF) { + long now = System.currentTimeMillis(); + if (CACHE != now) { + CACHE = now; + SDF.format(now); + } + } + counter++; + if (done) { + return; + } + } + } + + void jodaRun() { + for (;;) { + long now = System.currentTimeMillis(); + if (isCacheStale(now)) { + JODA.print(now); + } + counter++; + if (done) { + return; + } + } + } + + private static boolean isCacheStale(long now) { + synchronized (JODA) { + if (CACHE != now) { + CACHE = now; + return true; + } + } + return false; + } + +} Modified: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockThroughput.java ============================================================================== --- logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockThroughput.java (original) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/LockThroughput.java Mon Jun 15 20:55:01 2009 @@ -1,7 +1,6 @@ package ch.qos.logback.core.issue; -import java.util.concurrent.locks.Lock; -import java.util.concurrent.locks.ReentrantLock; +import ch.qos.logback.core.issue.SelectiveLockRunnable.LockingModel; /** * Short sample code testing the throughput of a fair lock. @@ -9,133 +8,39 @@ * @author Joern Huxhorn * @author Ceki Gulcu */ -public class LockThroughput implements Runnable { +public class LockThroughput { - enum LockingModel { - SYNC, FAIR, UNFAIR; - } - - static int THREAD_COUNT = 2; + static int THREAD_COUNT = 10; 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; - } + ThreadedThroughputCalculator tp = new ThreadedThroughputCalculator( + OVERALL_DURATION_IN_MILLIS); + tp.printEnvironmentInfo("LockThroughput"); - void fairLockRun() { - for (;;) { - FAIR_LOCK.lock(); - COUNTER++; - FAIR_LOCK.unlock(); - if (done) { - return; - } + for (int i = 0; i < 2; i++) { + tp.execute(buildArray(LockingModel.SYNC)); + tp.execute(buildArray(LockingModel.UNFAIR)); + tp.execute(buildArray(LockingModel.FAIR)); } - } + + tp.execute(buildArray(LockingModel.SYNC)); + tp.printThroughput("Sync: "); - void unfairLockRun() { - for (;;) { - UNFAIR_LOCK.lock(); - COUNTER++; - UNFAIR_LOCK.unlock(); - if (done) { - return; - } - } - } + tp.execute(buildArray(LockingModel.UNFAIR)); + tp.printThroughput("Unfair: "); - void synchronizedRUn() { - for (;;) { - synchronized (LOCK) { - COUNTER++; - if (done) { - return; - } - } - } + tp.execute(buildArray(LockingModel.FAIR)); + tp.printThroughput("Fair: "); } - public void run() { - switch (model) { - case SYNC: - synchronizedRUn(); - break; - case FAIR: - fairLockRun(); - break; - case UNFAIR: - unfairLockRun(); - break; + static SelectiveLockRunnable[] buildArray(LockingModel model) { + SelectiveLockRunnable[] array = new SelectiveLockRunnable[THREAD_COUNT]; + for (int i = 0; i < THREAD_COUNT; i++) { + array[i] = new SelectiveLockRunnable(model); } - } - - public String toString() { - return "counter=" + COUNTER; + return array; } } Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/RunnableForThrougputComputation.java ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/RunnableForThrougputComputation.java Mon Jun 15 20:55:01 2009 @@ -0,0 +1,26 @@ +package ch.qos.logback.core.issue; + +/** + * A runnable with 'done' and 'counter' fields. + * + * @author ceki + * + */ +abstract public class RunnableForThrougputComputation implements Runnable { + + protected boolean done = false; + protected int counter = 0; + + public int getCounter() { + return counter; + } + + public void setDone(boolean done) { + this.done = done; + } + + public boolean isDone() { + return done; + } + +} Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/SelectiveLockRunnable.java ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/SelectiveLockRunnable.java Mon Jun 15 20:55:01 2009 @@ -0,0 +1,74 @@ +package ch.qos.logback.core.issue; + +import java.util.concurrent.locks.Lock; +import java.util.concurrent.locks.ReentrantLock; + +/** + * A runnable which behaves differently depending on the desired locking model. + * + * @author Joern Huxhorn + * @author Ceki Gulcu + */ +public class SelectiveLockRunnable extends RunnableForThrougputComputation { + + enum LockingModel { + SYNC, FAIR, UNFAIR; + } + + static Object LOCK = new Object(); + static Lock FAIR_LOCK = new ReentrantLock(true); + static Lock UNFAIR_LOCK = new ReentrantLock(false); + + + LockingModel model; + + SelectiveLockRunnable(LockingModel model) { + this.model = model; + } + + public void run() { + switch (model) { + case SYNC: + synchronizedRUn(); + break; + case FAIR: + fairLockRun(); + break; + case UNFAIR: + unfairLockRun(); + break; + } + } + 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; + } + } + } +} Added: logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/ThreadedThroughputCalculator.java ============================================================================== --- (empty file) +++ logback/trunk/logback-core/src/test/java/ch/qos/logback/core/issue/ThreadedThroughputCalculator.java Mon Jun 15 20:55:01 2009 @@ -0,0 +1,67 @@ +package ch.qos.logback.core.issue; + +/** + * + * Useful scaffolding to measure the throughput of certain operations when + * invoked by multiple threads. + * + * @author Joern Huxhorn + * @author Ralph Goers + * @author Ceki Gulcu + */ +public class ThreadedThroughputCalculator { + + RunnableForThrougputComputation[] runnableArray; + Thread[] threadArray; + final long overallDurationInMillis; + + public ThreadedThroughputCalculator(long overallDurationInMillis) { + this.overallDurationInMillis = overallDurationInMillis; + } + + public void printEnvironmentInfo(String msg) { + System.out.println("=== "+ msg +" ==="); + 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 void execute(RunnableForThrougputComputation[] runnableArray) + throws InterruptedException { + this.runnableArray = runnableArray; + Thread[] threadArray = new Thread[runnableArray.length]; + + for (int i = 0; i < runnableArray.length; i++) { + threadArray[i] = new Thread(runnableArray[i]); + } + for (Thread t : threadArray) { + t.start(); + } + // let the threads run for a while + Thread.sleep(overallDurationInMillis); + + for (RunnableForThrougputComputation r : runnableArray) { + r.setDone(true); + } + for (Thread t : threadArray) { + t.join(); + } + } + + public void printThroughput(String msg) throws InterruptedException { + int sum = 0; + for (RunnableForThrougputComputation r : runnableArray) { + sum += r.getCounter(); + } + System.out.println(msg + "total of " + sum + " operations, or " + + (sum / overallDurationInMillis) + " operations per millisecond"); + } + +}