[logback-dev] svn commit: r1855 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic
Ralph Goers
ralph.goers at dslextreme.com
Tue Oct 21 01:07:21 CEST 2008
I'm having trouble getting the new version of LoggerPerfTest to pass.
I've attached the output of the test.
Ralph
noreply.ceki at qos.ch wrote:
> Author: ceki
> Date: Mon Oct 20 21:57:39 2008
> New Revision: 1855
>
> Modified:
> logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java
>
> Log:
> Related to LBCORE-58
>
> SleepAppender can derive from UnsynchronizedAppenderBase
>
>
> Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java
> ==============================================================================
> --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java (original)
> +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java Mon Oct 20 21:57:39 2008
> @@ -9,89 +9,111 @@
> */
> package ch.qos.logback.classic;
>
> +import static org.junit.Assert.assertTrue;
>
> -import java.net.InetAddress;
> -
> -import junit.framework.TestCase;
> -
> +import org.junit.Before;
> +import org.junit.Test;
> import org.slf4j.helpers.BogoPerf;
>
> import ch.qos.logback.classic.spi.LoggingEvent;
> import ch.qos.logback.classic.turbo.NOPTurboFilter;
> +import ch.qos.logback.core.UnsynchronizedAppenderBase;
> import ch.qos.logback.core.appender.NOPAppender;
>
> -public class LoggerPerfTest extends TestCase {
> -
> - final static String KAL = "kal";
> - String localhostName = null;
> - static long NORMAL_RUN_LENGTH = 1000*1000;
> +public class LoggerPerfTest {
>
> + long NANOS_IN_ONE_SEC = 1000*1000*1000L;
> + static long NORMAL_RUN_LENGTH = 1000 * 1000;
> + static long SHORTENED_RUN_LENGTH = 500 * 1000;
> static long REFERENCE_BIPS = 9324;
> -
> +
> + @Before
> public void setUp() throws Exception {
> - localhostName = InetAddress.getLocalHost().getCanonicalHostName();
> }
> - public void testBasic() {
> - basicDurationInNanos(NORMAL_RUN_LENGTH);
> - double avg = basicDurationInNanos(NORMAL_RUN_LENGTH);
> -
> +
> + @Test
> + public void testDurationOfDisabledLogWithStraightStringParameter() {
> + computeDurationOfDisabledLogWithStraightStringParameter(NORMAL_RUN_LENGTH);
> + double avg = computeDurationOfDisabledLogWithStraightStringParameter(NORMAL_RUN_LENGTH);
> +
> long referencePerf = 17;
> BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS);
> - //System.out.println("Average log time for disabled statements: "+avg+" nanos.");
> - }
> -
> - public void testParameterized() {
> - loopParameterized(NORMAL_RUN_LENGTH);
> - double avgDuration = loopParameterized(NORMAL_RUN_LENGTH);
> - long referencePerf = 36;
> - BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS);
> - //System.out.println("Average log time for disabled (parameterized) statements: "+avg+" nanos.");
> }
> -
> -
> - public void testNOPFilter() {
> - loopNopFilter(NORMAL_RUN_LENGTH);
> - double avg = loopNopFilter(NORMAL_RUN_LENGTH);
> - //System.out.println("Average log time for disabled (NOPFilter) statements: "+avg+" nanos.");
> - long referencePerf = 48;
> - BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS);
> - }
> -
> - double basicDurationInNanos(long len) {
> +
> + double computeDurationOfDisabledLogWithStraightStringParameter(long len) {
> LoggerContext lc = new LoggerContext();
> - NOPAppender<LoggingEvent> mopAppender = new NOPAppender<LoggingEvent>();
> - mopAppender.start();
> Logger logger = lc.getLogger(this.getClass());
> logger.setLevel(Level.OFF);
> - for(long i = 0; i < len; i++) {
> + for (long i = 0; i < len; i++) {
> logger.debug("Toto");
> }
> long start = System.nanoTime();
> - for(long i = 0; i < len; i++) {
> + for (long i = 0; i < len; i++) {
> logger.debug("Toto");
> }
> long end = System.nanoTime();
> - return (end-start)/len;
> + return (end - start) / len;
> }
>
> - double loopParameterized(long len) {
> + @Test
> + public void testDurationOfDisabledLogWithParameters() {
> + computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH);
> + double avgDuration = computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH);
> + long referencePerf = 36;
> + BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS);
> + }
> +
> + double computeDurationOfDisabledLogWithParameters(long len) {
> LoggerContext lc = new LoggerContext();
> - NOPAppender<LoggingEvent> mopAppender = new NOPAppender<LoggingEvent>();
> - mopAppender.start();
> Logger logger = lc.getLogger(this.getClass());
> logger.setLevel(Level.OFF);
> - for(long i = 0; i < len; i++) {
> + for (long i = 0; i < len; i++) {
> logger.debug("Toto {}", i);
> }
> long start = System.nanoTime();
> - for(long i = 0; i < len; i++) {
> + for (long i = 0; i < len; i++) {
> logger.debug("Toto {}", i);
> }
> long end = System.nanoTime();
> - return (end-start)/len;
> + return (end - start) / len;
> + }
> +
> + @Test
> + public void testDurationOfEnabledWithStraightStringParameter() {
> + computeDurationOfEnabledLogWithStraightStringParameter(SHORTENED_RUN_LENGTH);
> + double avgDuration = computeDurationOfEnabledLogWithStraightStringParameter(SHORTENED_RUN_LENGTH);
> + long referencePerf = 500;
> + BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS);
> + System.out.println("avgDuration="+avgDuration);
> }
>
> - double loopNopFilter(long len) {
> + double computeDurationOfEnabledLogWithStraightStringParameter(long len) {
> + LoggerContext lc = new LoggerContext();
> + Logger logger = lc.getLogger(this.getClass());
> + logger.setLevel(Level.ALL);
> + NOPAppender<LoggingEvent> nopAppender = new NOPAppender<LoggingEvent>();
> + nopAppender.start();
> + logger.addAppender(nopAppender);
> + for (long i = 0; i < len; i++) {
> + logger.debug("Toto", i);
> + }
> + long start = System.nanoTime();
> + for (long i = 0; i < len; i++) {
> + logger.debug("Toto");
> + }
> + long end = System.nanoTime();
> + return (end - start) / len;
> + }
> +
> + @Test
> + public void testComputeDurationOfDisabledLogsWithNOPFilter() {
> + computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH);
> + double avg = computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH);
> + long referencePerf = 48;
> + BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS);
> + }
> +
> + double computeDurationOfDisabledLogsWithNOPFilter(long len) {
> LoggerContext lc = new LoggerContext();
> NOPAppender<LoggingEvent> mopAppender = new NOPAppender<LoggingEvent>();
> NOPTurboFilter nopFilter = new NOPTurboFilter();
> @@ -100,15 +122,92 @@
> lc.addTurboFilter(nopFilter);
> Logger logger = lc.getLogger(this.getClass());
> logger.setLevel(Level.OFF);
> - for(long i = 0; i < len; i++) {
> + for (long i = 0; i < len; i++) {
> logger.debug("Toto");
> }
> long start = System.nanoTime();
> - for(long i = 0; i < len; i++) {
> + for (long i = 0; i < len; i++) {
> logger.debug("Toto");
> }
> long end = System.nanoTime();
> - return (end-start)/len;
> + return (end - start) / len;
> }
> -
> +
> + @Test
> + public void testThreadedLogging() throws InterruptedException {
> + LoggerContext lc = new LoggerContext();
> + SleepAppender<LoggingEvent> appender = new SleepAppender<LoggingEvent>();
> +
> + int MILLIS_PER_CALL = 250;
> + int NANOS_PER_CALL = 250*1000*1000;;
> + appender.setDuration(MILLIS_PER_CALL);
> + appender.start();
> + Logger logger = lc.getLogger(this.getClass());
> + logger.addAppender(appender);
> + logger.setLevel(Level.DEBUG);
> + long start;
> + long end;
> + int threadCount = 10;
> + int iterCount = 5;
> + TestRunner[] threads = new TestRunner[threadCount];
> + for (int i = 0; i < threads.length; ++i) {
> + threads[i] = new TestRunner(logger, iterCount);
> + }
> + start = System.nanoTime();
> + for (Thread thread : threads) {
> + thread.start();
> + }
> + for (TestRunner thread : threads) {
> + thread.join();
> + }
> + end = System.nanoTime();
> + double tolerance = threadCount * .125; // Very little thread contention
> + // should occur in this test.
> + double max = ((((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount) * tolerance;
> + double serialized = (((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount
> + * threadCount;
> + double actual = ((double) (end - start)) / NANOS_IN_ONE_SEC;
> + System.out
> + .printf(
> + "Sleep duration: %,.4f seconds. Max expected: %,.4f seconds, Serialized: %,.4f\n",
> + actual, max, serialized);
> + assertTrue("Exceeded maximum expected time.", actual < max);
> + }
> +
> + // ============================================================
> + private static class TestRunner extends Thread {
> + private Logger logger;
> + private long len;
> +
> + public TestRunner(Logger logger, long len) {
> + this.logger = logger;
> + this.len = len;
> + }
> +
> + public void run() {
> + Thread.yield();
> + for (long i = 0; i < len; i++) {
> + logger.debug("Toto");
> + }
> + }
> + }
> +
> + // ============================================================
> + public static class SleepAppender<E> extends UnsynchronizedAppenderBase<E> {
> + private static long duration = 500;
> +
> + public void setDuration(long millis) {
> + duration = millis;
> + }
> +
> + @Override
> + protected void append(E eventObject) {
> + try {
> + Thread.sleep(duration);
> + } catch (InterruptedException ie) {
> + // Ignore
> + }
> + }
> + }
> + // ============================================================
> }
> _______________________________________________
> logback-dev mailing list
> logback-dev at qos.ch
> http://qos.ch/mailman/listinfo/logback-dev
>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: ch.qos.logback.classic.LoggerPerfTest.txt
Url: http://qos.ch/pipermail/logback-dev/attachments/20081020/ab2e5340/attachment-0001.txt
More information about the logback-dev
mailing list