Author: ceki Date: Wed Jul 15 13:15:03 2009 New Revision: 2351 Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/PackageTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java Log: - cosmetic changes - added performance testing concerning ReconfigureOnChangeFilter (ongoing work) Related to LBCORE-59 Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java Wed Jul 15 13:15:03 2009 @@ -49,7 +49,7 @@ synchronized (context) { long inSeconds = refreshPeriod / 1000; addInfo("Will scan for changes in file [" + fileToScan + "] every " - + inSeconds + " seconds. "+stem()); + + inSeconds + " seconds. "); lastModified = fileToScan.lastModified(); updateNextCheck(System.currentTimeMillis()); } @@ -71,12 +71,12 @@ } } - // a counter of the number of time the decide method is called + // The next fields counts the number of time the decide method is called + // // IMPORTANT: This field can be updated by multiple threads. It follows that - // its values may not be incremented sequentially. However, we don't care + // its values may *not* be incremented sequentially. However, we don't care // about the actual value of the field except that from time to time the // expression (invocationCounter++ & 0xF) == 0xF) should be true. - private int invocationCounter = 0; @Override @@ -94,8 +94,7 @@ synchronized (context) { boolean changed = changeDetected(); if (changed) { - addInfo("[" + fileToScan + "] change detected. Reconfiguring. "+stem()); - + addInfo("[" + fileToScan + "] change detected. Reconfiguring. "); addInfo("Resetting and reconfiguring context [" + context.getName() + "]"); reconfigure(); @@ -108,10 +107,10 @@ nextCheck = now + refreshPeriod; } - String stem() { - return currentThreadName() + ", context " + context.getName() - + ", nextCheck=" + (nextCheck - INIT); - } +// String stem() { +// return currentThreadName() + ", context " + context.getName() +// + ", nextCheck=" + (nextCheck - INIT); +// } // This method is synchronized to prevent near-simultaneous re-configurations protected boolean changeDetected() { Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/PackageTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/PackageTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/PackageTest.java Wed Jul 15 13:15:03 2009 @@ -1,20 +1,21 @@ /** * Logback: the generic, reliable, fast and flexible logging framework. * - * Copyright (C) 1999-2006, QOS.ch + * Copyright (C) 2000-2009, QOS.ch * * This library is free software, you can redistribute it and/or modify it under * the terms of the GNU Lesser General Public License as published by the Free * Software Foundation. */ -package ch.qos.logback.classic.turbo; +package ch.qos.logback.classic.turbo; import org.junit.runner.RunWith; import org.junit.runners.Suite; import org.junit.runners.Suite.SuiteClasses; @RunWith(Suite.class) -@SuiteClasses( { MarkerFilterTest.class, DuplicateMessageFilterTest.class}) -public class PackageTest { +@SuiteClasses( { ReconfigureOnChangeTest.class, MarkerFilterTest.class, + DuplicateMessageFilterTest.class }) +public class PackageTest { } \ No newline at end of file Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeTest.java Wed Jul 15 13:15:03 2009 @@ -4,25 +4,30 @@ import java.io.File; import java.io.IOException; +import java.net.MalformedURLException; import org.junit.Test; +import ch.qos.logback.classic.Level; import ch.qos.logback.classic.Logger; import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.issue.lbclassic135.LoggingRunnable; import ch.qos.logback.classic.joran.JoranConfigurator; import ch.qos.logback.classic.util.TeztConstants; +import ch.qos.logback.core.CoreConstants; import ch.qos.logback.core.contention.MultiThreadedHarness; import ch.qos.logback.core.contention.RunnableWithCounterAndDone; import ch.qos.logback.core.joran.spi.JoranException; import ch.qos.logback.core.status.StatusChecker; -import ch.qos.logback.core.util.StatusPrinter; public class ReconfigureOnChangeTest { LoggerContext loggerContext = new LoggerContext(); Logger logger = loggerContext.getLogger(this.getClass()); final static int THREAD_COUNT = 5; + String SCAN1_FILE_AS_STR = TeztConstants.TEST_DIR_PREFIX + + "input/turbo/scan1.xml"; + static int TOTAL_TEST_DURATION = 2000; // it actually takes time for Windows to propagate file modification changes // values below 100 milliseconds can be problematic @@ -49,26 +54,55 @@ // Tests whether ConfigurationAction is installing ReconfigureOnChangeFilter @Test public void scan1() throws JoranException, IOException, InterruptedException { - - String configFileAsStr = TeztConstants.TEST_DIR_PREFIX - + "input/turbo/scan1.xml"; - configure(configFileAsStr); - - File file = new File(configFileAsStr); + configure(SCAN1_FILE_AS_STR); + File file = new File(SCAN1_FILE_AS_STR); RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(file); harness.execute(runnableArray); long expectedRreconfigurations = runnableArray[0].getCounter(); StatusChecker checker = new StatusChecker(loggerContext); - StatusPrinter.print(loggerContext); + //StatusPrinter.print(loggerContext); assertTrue(checker.isErrorFree()); - int result = checker.matchCount("Resetting and reconfiguring context"); - assertTrue(expectedRreconfigurations >= result); + int effectiveResets = checker.matchCount("Resetting and reconfiguring context"); + // the number of effective resets must be equal or less than expectedRreconfigurations + assertTrue(effectiveResets <= expectedRreconfigurations); + // however, there should be some effective resets + assertTrue((effectiveResets * 1.1) >= (expectedRreconfigurations * 1.0)); } - - + @Test + public void perfTest() throws MalformedURLException { + ReconfigureOnChangeFilter rocf = new ReconfigureOnChangeFilter(); + rocf.setContext(loggerContext); + File file = new File(SCAN1_FILE_AS_STR); + loggerContext.putObject(CoreConstants.URL_OF_LAST_CONFIGURATION_VIA_JORAN, + file.toURI().toURL()); + rocf.start(); + assertTrue(rocf.isStarted()); + loggerContext.addTurboFilter(rocf); + + final int loopLen = 1000*1000; + + loop(loopLen, rocf); + loop(loopLen, rocf); + double avg = loop(loopLen, rocf); + System.out.println(avg); + // the reference was computed on Orion (Ceki's computer) + //long referencePerf = 5000; + //BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS); + } + + public double loop(int loopLen, ReconfigureOnChangeFilter rocf) { + long start = System.nanoTime(); + for (int i = 0; i < loopLen; i++) { + //logger.debug("hello"); + rocf.decide(null, logger, Level.DEBUG, " ", null, null); + } + long end = System.nanoTime(); + return (end - start) / (1.0d * loopLen); + } + class Updater extends RunnableWithCounterAndDone { File configFile;