[logback-dev] svn commit: r2351 - in logback/trunk/logback-classic/src: main/java/ch/qos/logback/classic/turbo test/java/ch/qos/logback/classic/turbo
noreply.ceki at qos.ch
noreply.ceki at qos.ch
Wed Jul 15 13:15:04 CEST 2009
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)
- at SuiteClasses( { MarkerFilterTest.class, DuplicateMessageFilterTest.class})
-public class PackageTest {
+ at 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;
More information about the logback-dev
mailing list