This is an automated email from the git hooks/post-receive script. It was generated because a ref change was pushed to the repository containing the project "Logback: the generic, reliable, fast and flexible logging framework.". The branch, master has been updated via 608ed4c58717296b8182006e35aff52ca2ecb598 (commit) via 1f6b71923bfeb5d273a80388e7dca2edab02677c (commit) from d886e9b0aa31036bf5bf5c5b78249afb50a80d6c (commit) Those revisions listed above that are new to this repository have not appeared on any other notification email; so we list those revisions in full, below. - Log ----------------------------------------------------------------- http://git.qos.ch/gitweb/?p=logback.git;a=commit;h=608ed4c58717296b8182006e3... http://github.com/ceki/logback/commit/608ed4c58717296b8182006e35aff52ca2ecb5... commit 608ed4c58717296b8182006e35aff52ca2ecb598 Author: Ceki Gulcu <ceki@qos.ch> Date: Wed Apr 25 23:47:18 2012 +0200 fix LBCORE-221 diff --git a/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java b/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java index c038354..c812c2b 100644 --- a/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java +++ b/logback-classic/src/main/java/ch/qos/logback/classic/turbo/ReconfigureOnChangeFilter.java @@ -33,6 +33,8 @@ import ch.qos.logback.classic.joran.JoranConfigurator; import ch.qos.logback.core.joran.spi.JoranException; import ch.qos.logback.core.spi.FilterReply; +import static ch.qos.logback.core.CoreConstants.MILLIS_IN_ONE_SECOND; + /** * Reconfigure a LoggerContext when the configuration file changes. * @@ -44,7 +46,7 @@ public class ReconfigureOnChangeFilter extends TurboFilter { * Scan for changes in configuration file once every minute. */ // 1 minute - value mentioned in documentation - public final static long DEFAULT_REFRESH_PERIOD = 60 * 1000; + public final static long DEFAULT_REFRESH_PERIOD = 60 * MILLIS_IN_ONE_SECOND; long refreshPeriod = DEFAULT_REFRESH_PERIOD; URL mainConfigurationURL; @@ -85,6 +87,10 @@ public class ReconfigureOnChangeFilter extends TurboFilter { // expression (invocationCounter++ & 0xF) == 0xF) should be true. private long invocationCounter = 0; + private volatile long mask = 0xF; + private long lastMaskCheck = System.currentTimeMillis(); + + @Override public FilterReply decide(Marker marker, Logger logger, Level level, String format, Object[] params, Throwable t) { @@ -92,14 +98,17 @@ public class ReconfigureOnChangeFilter extends TurboFilter { return FilterReply.NEUTRAL; } - // for performance reasons, skip any type of computation 15 times out of 16. - // Only once every 16 calls is the check for elapsed type is performed - if (((invocationCounter++) & 0xF) != 0xF) { + // for performance reasons, skip any type of computation (MASK-1) times out of MASK. + // Only once every MASK calls is the check for elapsed time is performed + if (((invocationCounter++) & mask) != mask) { return FilterReply.NEUTRAL; } + long now = System.currentTimeMillis(); + synchronized (configurationWatchList) { - if (changeDetected()) { + updateMaskIfNecessary(now); + if (changeDetected(now)) { // Even though reconfiguration involves resetting the loggerContext, // which clears the list of turbo filters including this instance, it is // still possible for this instance to be subsequently invoked by another @@ -112,6 +121,20 @@ public class ReconfigureOnChangeFilter extends TurboFilter { return FilterReply.NEUTRAL; } + // for CPU intensive applications with 200 or more threads MASK values in the order of 0xFFFF is appropriate + private static final int MAX_MASK = 0xFFFF; + + private void updateMaskIfNecessary(long now) { + if (now - lastMaskCheck < MILLIS_IN_ONE_SECOND) { + if (mask < MAX_MASK) { + mask = (mask << 1) | 1; + } + } else { + mask = mask >>> 2; + } + lastMaskCheck = now; + } + // by detaching reconfiguration to a new thread, we release the various // locks held by the current thread, in particular, the AppenderAttachable // reader lock. @@ -124,8 +147,7 @@ public class ReconfigureOnChangeFilter extends TurboFilter { nextCheck = now + refreshPeriod; } - protected boolean changeDetected() { - long now = System.currentTimeMillis(); + protected boolean changeDetected(long now) { if (now >= nextCheck) { updateNextCheck(now); return configurationWatchList.changeDetected(); @@ -152,7 +174,7 @@ public class ReconfigureOnChangeFilter extends TurboFilter { return; } LoggerContext lc = (LoggerContext) context; - addInfo(CoreConstants.RESET_MSG_PREFIX + "named ["+context.getName() + "]"); + addInfo(CoreConstants.RESET_MSG_PREFIX + "named [" + context.getName() + "]"); if (mainConfigurationURL.toString().endsWith("xml")) { performXMLConfiguration(lc); } else if (mainConfigurationURL.toString().endsWith("groovy")) { diff --git a/logback-classic/src/test/input/turbo/scan_perf.xml b/logback-classic/src/test/input/turbo/scan_perf.xml index a5bc569..d652491 100644 --- a/logback-classic/src/test/input/turbo/scan_perf.xml +++ b/logback-classic/src/test/input/turbo/scan_perf.xml @@ -13,7 +13,8 @@ </appender> - <root level="DEBUG"> + <!-- level should be ERROR so as not to incur IO --> + <root level="ERROR"> <appender-ref ref="FILE"/> </root> diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java b/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java index b8ce4bd..dd93afb 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/turbo/ReconfigurePerf.java @@ -17,6 +17,7 @@ import java.io.File; import java.io.IOException; import org.junit.Before; +import org.junit.Ignore; import org.junit.Test; import ch.qos.logback.classic.ClassicTestConstants; @@ -29,14 +30,15 @@ import ch.qos.logback.core.contention.RunnableWithCounterAndDone; import ch.qos.logback.core.joran.spi.JoranException; import ch.qos.logback.core.testUtil.Env; +@Ignore public class ReconfigurePerf { - final static int THREAD_COUNT = 50; + final static int THREAD_COUNT = 500; //final static int LOOP_LEN = 1000 * 1000; // the space in the file name mandated by // http://jira.qos.ch/browse/LBCORE-119 final static String CONF_FILE_AS_STR = ClassicTestConstants.INPUT_PREFIX - + "turbo/scan_perf_barebones.xml"; + + "turbo/scan_perf.xml"; // it actually takes time for Windows to propagate file modification changes // values below 100 milliseconds can be problematic the same propagation @@ -45,6 +47,7 @@ public class ReconfigurePerf { int sleepBetweenUpdates = DEFAULT_SLEEP_BETWEEN_UPDATES; + static int numberOfCycles = 150; static int totalTestDuration; LoggerContext loggerContext = new LoggerContext(); @@ -56,9 +59,9 @@ public class ReconfigurePerf { // take into account propagation latency occurs on Linux if (Env.isLinux()) { sleepBetweenUpdates = 850; - totalTestDuration = sleepBetweenUpdates * 25; + totalTestDuration = sleepBetweenUpdates * numberOfCycles; } else { - totalTestDuration = sleepBetweenUpdates * 50; + totalTestDuration = sleepBetweenUpdates * numberOfCycles * 2; } harness = new MultiThreadedHarness(totalTestDuration); } @@ -82,11 +85,7 @@ public class ReconfigurePerf { public void scan1() throws JoranException, IOException, InterruptedException { File file = new File(CONF_FILE_AS_STR); configure(file); - //doRun(); - //doRun(); - //doRun(); - System.out.println("ENTER :"); - //System.in.read(); + System.out.println("Running scan1()"); doRun(); } @@ -94,29 +93,4 @@ public class ReconfigurePerf { RunnableWithCounterAndDone[] runnableArray = buildRunnableArray(); harness.execute(runnableArray); } - -// ReconfigureOnChangeFilter initROCF() throws MalformedURLException { -// ReconfigureOnChangeFilter rocf = new ReconfigureOnChangeFilter(); -// rocf.setContext(loggerContext); -// File file = new File(CONF_FILE_AS_STR); -// loggerContext.putObject(CoreConstants.URL_OF_LAST_CONFIGURATION_VIA_JORAN, -// file.toURI().toURL()); -// rocf.start(); -// return rocf; -// } - - -// public double directLoop(ReconfigureOnChangeFilter rocf) { -// long start = System.nanoTime(); -// for (int i = 0; i < LOOP_LEN; i++) { -// rocf.decide(null, logger, Level.DEBUG, " ", null, null); -// } -// long end = System.nanoTime(); -// return (end - start) / (1.0d * LOOP_LEN); -// } -// -// void addInfo(String msg, Object o) { -// loggerContext.getStatusManager().add(new InfoStatus(msg, o)); -// } - } diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/FileNamePattern.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/FileNamePattern.java index dab1a72..c96d515 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/FileNamePattern.java +++ b/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/FileNamePattern.java @@ -165,7 +165,7 @@ public class FileNamePattern extends ContextAwareBase { if (p instanceof LiteralConverter) { buf.append(p.convert(null)); } else if (p instanceof IntegerTokenConverter) { - buf.append("(\\d{1,2})"); + buf.append("(\\d{1,3})"); } else if (p instanceof DateTokenConverter) { buf.append(p.convert(date)); } diff --git a/logback-site/src/site/pages/news.html b/logback-site/src/site/pages/news.html index 37ba9ff..6b88b35 100644 --- a/logback-site/src/site/pages/news.html +++ b/logback-site/src/site/pages/news.html @@ -31,12 +31,27 @@ <h3>Xth of April, 2012 - Release of version 1.0.2</h3> + + <p><code>ReconfigureOnChangeFilter</code> will avoid excessive + syncronization in case of CPU intensive applications. This fixes + <a + href="http://jira.qos.ch/browse/LBCLASSIC-234">LBCLASSIC-234</a>, + a recalcitrant bug reported by Uri Unger who also provided the key + steps for reproducing it. + </p> + <p><code>RollingFileAppender</code> now creates missing directories for compressed archive files. This fixes <a href="http://jira.qos.ch/browse/LBCORE-169">LBCORE-169</a> - reported by Tomasz Nurkiewicz with patchessupplied by Paulo + reported by Tomasz Nurkiewicz with patches supplied by Paulo Andrade and Mats Henrikson. </p> + + <p><code>SizeAndTimeBasedFNATP</code> will now remove files with + indexes higher than 99. It will also correctly compute the highest + index value when an application is restarted. This fixes bug <a + href="http://jira.qos.ch/browse/LBCORE-221">LBCORE-221</a> + reported by Dieter Mueller and Dawid Chodura.</p> <hr width="80%" align="center" /> http://git.qos.ch/gitweb/?p=logback.git;a=commit;h=1f6b71923bfeb5d273a80388e... http://github.com/ceki/logback/commit/1f6b71923bfeb5d273a80388e7dca2edab0267... commit 1f6b71923bfeb5d273a80388e7dca2edab02677c Author: Ceki Gulcu <ceki@qos.ch> Date: Tue Apr 24 20:05:57 2012 +0200 added blurb on LBCORE-169 diff --git a/logback-site/src/site/pages/news.html b/logback-site/src/site/pages/news.html index ef261da..37ba9ff 100644 --- a/logback-site/src/site/pages/news.html +++ b/logback-site/src/site/pages/news.html @@ -29,6 +29,18 @@ <hr width="80%" align="center" /> + <h3>Xth of April, 2012 - Release of version 1.0.2</h3> + + <p><code>RollingFileAppender</code> now creates missing + directories for compressed archive files. This fixes <a + href="http://jira.qos.ch/browse/LBCORE-169">LBCORE-169</a> + reported by Tomasz Nurkiewicz with patchessupplied by Paulo + Andrade and Mats Henrikson. + </p> + + + <hr width="80%" align="center" /> + <h3>7th of March, 2012 - Release of version 1.0.1</h3> <p>Setting the debug attribute to true in the ----------------------------------------------------------------------- Summary of changes: .../classic/turbo/ReconfigureOnChangeFilter.java | 38 ++++++++++++++---- logback-classic/src/test/input/turbo/scan_perf.xml | 3 +- .../qos/logback/classic/turbo/ReconfigurePerf.java | 42 ++++---------------- .../core/rolling/helper/FileNamePattern.java | 2 +- logback-site/src/site/pages/news.html | 27 +++++++++++++ 5 files changed, 68 insertions(+), 44 deletions(-) hooks/post-receive -- Logback: the generic, reliable, fast and flexible logging framework.