Author: ceki Date: Mon Jun 29 17:43:52 2009 New Revision: 2310 Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/DateConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MDCConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/RelativeTimeConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/SyslogStartConverter.java logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/TargetLengthBasedClassNameAbbreviator.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/UnsynchronizedAppenderBase.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/WriterAppender.java Log: Diminish contention in appender doAppender. Relates to LBCLASSIC-135 Instead of the doAppend method being synchronized, WriterAppender now uses UnsynchronizedAppenderBase as its super class. Consequently, various converters can no longer assume that they are invoked from within a synchronized block. Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/CallerDataConverter.java Mon Jun 29 17:43:52 2009 @@ -65,7 +65,6 @@ } } } - } private void addEvaluator(EventEvaluator<ILoggingEvent> ee) { @@ -76,7 +75,7 @@ } public String convert(ILoggingEvent le) { - StringBuffer buf = new StringBuffer(); + StringBuilder buf = new StringBuilder(); if (evaluatorList != null) { boolean printCallerData = false; Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/DateConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/DateConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/DateConverter.java Mon Jun 29 17:43:52 2009 @@ -17,56 +17,58 @@ import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.core.CoreConstants; - public class DateConverter extends ClassicConverter { - + long lastTimestamp = -1; - String timesmapStr = null; + String timestampStrCache = null; SimpleDateFormat simpleFormat = null; - + public void start() { - + String datePattern = getFirstOption(); - if(datePattern == null) { + if (datePattern == null) { datePattern = CoreConstants.ISO8601_PATTERN; } - + if (datePattern.equals(CoreConstants.ISO8601_STR)) { datePattern = CoreConstants.ISO8601_PATTERN; - } - + } + try { simpleFormat = new SimpleDateFormat(datePattern); - //maximumCacheValidity = CachedDateFormat.getMaximumCacheValidity(pattern); + // maximumCacheValidity = + // CachedDateFormat.getMaximumCacheValidity(pattern); } catch (IllegalArgumentException e) { - addWarn("Could not instantiate SimpleDateFormat with pattern " + datePattern, e); + addWarn("Could not instantiate SimpleDateFormat with pattern " + + datePattern, e); // default to the ISO8601 format simpleFormat = new SimpleDateFormat(CoreConstants.ISO8601_PATTERN); } - + List optionList = getOptionList(); - + // if the option list contains a TZ option, then set it. if (optionList != null && optionList.size() > 1) { TimeZone tz = TimeZone.getTimeZone((String) optionList.get(1)); simpleFormat.setTimeZone(tz); } } - + public String convert(ILoggingEvent le) { long timestamp = le.getTimeStamp(); - - // if called multiple times within the same millisecond - // return old value - if(timestamp == lastTimestamp) { - return timesmapStr; - } else { - lastTimestamp = timestamp; - // SimpleDateFormat is not thread safe. However, since - // the AppenderBase.doAppend is synchronized, we are should be - // OK. See also http://jira.qos.ch/browse/LBCLASSIC-36 - timesmapStr = simpleFormat.format(new Date(timestamp)); - return timesmapStr; + + synchronized (this) { + // if called multiple times within the same millisecond + // return cache value + if (timestamp == lastTimestamp) { + return timestampStrCache; + } else { + lastTimestamp = timestamp; + // SimpleDateFormat is not thread safe. + // See also http://jira.qos.ch/browse/LBCLASSIC-36 + timestampStrCache = simpleFormat.format(new Date(timestamp)); + return timestampStrCache; + } } } } Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MDCConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MDCConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/MDCConverter.java Mon Jun 29 17:43:52 2009 @@ -37,7 +37,7 @@ if (key == null) { // if no key is specified, return all the // values present in the MDC, separated with a single space. - StringBuffer buf = new StringBuffer(); + StringBuilder buf = new StringBuilder(); Set<String> keys = mdcPropertyMap.keySet(); Iterator it = keys.iterator(); String tmpKey; Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/RelativeTimeConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/RelativeTimeConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/RelativeTimeConverter.java Mon Jun 29 17:43:52 2009 @@ -14,19 +14,18 @@ public class RelativeTimeConverter extends ClassicConverter { long lastTimestamp = -1; - String timesmapStr = null; - + String timesmapCache = null; + public String convert(ILoggingEvent event) { - long timestamp = event.getTimeStamp(); - - // if called multiple times within the same millisecond - // return old value - if(timestamp == lastTimestamp) { - return timesmapStr; - } else { - lastTimestamp = timestamp; - timesmapStr = Long.toString(timestamp - event.getLoggerContextVO().getBirthTime()); - return timesmapStr; + long now = event.getTimeStamp(); + + synchronized (this) { + // update timesmapStrCache only if now != lastTimestamp + if (now != lastTimestamp) { + lastTimestamp = now; + timesmapCache = Long.toString(now - event.getLoggerContextVO().getBirthTime()); + } + return timesmapCache; } } } Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/SyslogStartConverter.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/SyslogStartConverter.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/SyslogStartConverter.java Mon Jun 29 17:43:52 2009 @@ -61,7 +61,7 @@ sb.append("<"); sb.append(pri); sb.append(">"); - fillInTimestamp(sb, event.getTimeStamp()); + sb.append(computeTimeStampString(event.getTimeStamp())); sb.append(' '); sb.append(localHostName); sb.append(' '); @@ -85,13 +85,13 @@ } } - void fillInTimestamp(StringBuilder sb, long timestamp) { - // if called multiple times within the same millisecond - // use last value - if (timestamp != lastTimestamp) { - lastTimestamp = timestamp; - timesmapStr = simpleFormat.format(new Date(timestamp)); + String computeTimeStampString(long now) { + synchronized (this) { + if (now != lastTimestamp) { + lastTimestamp = now; + timesmapStr = simpleFormat.format(new Date(now)); + } + return timesmapStr; } - sb.append(timesmapStr); - } + } } Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/TargetLengthBasedClassNameAbbreviator.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/TargetLengthBasedClassNameAbbreviator.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/pattern/TargetLengthBasedClassNameAbbreviator.java Mon Jun 29 17:43:52 2009 @@ -14,17 +14,14 @@ public class TargetLengthBasedClassNameAbbreviator implements Abbreviator { - static private final int BUF_LIMIT = 256; - final int targetLength; - StringBuffer buf; public TargetLengthBasedClassNameAbbreviator(int targetLength) { - this.targetLength = targetLength; - buf = new StringBuffer(targetLength); + this.targetLength = targetLength; } public String abbreviate(String fqClassName) { + StringBuilder buf = new StringBuilder(targetLength); if (fqClassName == null) { throw new IllegalArgumentException("Class name may not be null"); } @@ -34,11 +31,6 @@ return fqClassName; } - if (buf.capacity() > BUF_LIMIT) { - buf = new StringBuffer(targetLength); - } - buf.setLength(0); - int[] dotIndexesArray = new int[ClassicConstants.MAX_DOTS]; // a.b.c contains 2 dots but 2+1 parts. // see also http://jira.qos.ch/browse/LBCLASSIC-110 Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PubLoggingEventVO.java Mon Jun 29 17:43:52 2009 @@ -21,7 +21,7 @@ import ch.qos.logback.classic.Level; /** - * A read/write and serializable implementation of {@link ILoggingEvent}. + * A read/write and serializable implementation of {@link ILoggingEvent}. * * @author Ceki Gülcü Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/UnsynchronizedAppenderBase.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/UnsynchronizedAppenderBase.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/UnsynchronizedAppenderBase.java Mon Jun 29 17:43:52 2009 @@ -58,7 +58,7 @@ private int statusRepeatCount = 0; private int exceptionCount = 0; - static final int ALLOWED_REPEATS = 5; + static final int ALLOWED_REPEATS = 3; public void doAppend(E eventObject) { // WARNING: The guard check MUST be the first statement in the Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/WriterAppender.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/WriterAppender.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/WriterAppender.java Mon Jun 29 17:43:52 2009 @@ -26,7 +26,7 @@ * * @author Ceki Gülcü */ -public class WriterAppender<E> extends AppenderBase<E> { +public class WriterAppender<E> extends UnsynchronizedAppenderBase<E> { /** * Immediate flush means that the underlying writer or output stream will be @@ -36,14 +36,16 @@ * is a good chance that the last few logs events are not actually written to * persistent media if and when the application crashes. * - * <p> The <code>immediateFlush</code> variable is set to <code>true</code> - * by default. + * <p> + * The <code>immediateFlush</code> variable is set to <code>true</code> by + * default. */ private boolean immediateFlush = true; /** - * The encoding to use when opening an InputStream. <p> The - * <code>encoding</code> variable is set to <code>null</null> by default + * The encoding to use when opening an InputStream. + * <p> + * The <code>encoding</code> variable is set to <code>null</null> by default * which results in the use of the system's default encoding. */ private String encoding; @@ -53,7 +55,6 @@ */ private Writer writer; - /** * The default constructor does nothing. */ @@ -64,12 +65,14 @@ * If the <b>ImmediateFlush</b> option is set to <code>true</code>, the * appender will flush at the end of each write. This is the default behavior. * If the option is set to <code>false</code>, then the underlying stream - * can defer writing to physical medium to a later time. <p> Avoiding the - * flush operation at the end of each append results in a performance gain of - * 10 to 20 percent. However, there is safety tradeoff involved in skipping - * flushing. Indeed, when flushing is skipped, then it is likely that the last - * few log events will not be recorded on disk when the application exits. - * This is a high price to pay even for a 20% performance gain. + * can defer writing to physical medium to a later time. + * <p> + * Avoiding the flush operation at the end of each append results in a + * performance gain of 10 to 20 percent. However, there is safety tradeoff + * involved in skipping flushing. Indeed, when flushing is skipped, then it is + * likely that the last few log events will not be recorded on disk when the + * application exits. This is a high price to pay even for a 20% performance + * gain. */ public void setImmediateFlush(boolean value) { immediateFlush = value; @@ -118,7 +121,8 @@ * Stop this appender instance. The underlying stream or writer is also * closed. * - * <p> Stopped appenders cannot be reused. + * <p> + * Stopped appenders cannot be reused. */ public synchronized void stop() { closeWriter(); @@ -177,7 +181,6 @@ encoding = value; } - void writeHeader() { if (layout != null && (this.writer != null)) { try { @@ -224,12 +227,13 @@ } /** - * <p> Sets the Writer where the log output will go. The specified Writer must - * be opened by the user and be writable. The <code>java.io.Writer</code> - * will be closed when the appender instance is closed. + * <p> + * Sets the Writer where the log output will go. The specified Writer must be + * opened by the user and be writable. The <code>java.io.Writer</code> will + * be closed when the appender instance is closed. * * @param writer - * An already opened Writer. + * An already opened Writer. */ public synchronized void setWriter(Writer writer) { // close any previously opened writer @@ -247,8 +251,10 @@ } /** - * Actual writing occurs here. <p> Most subclasses of - * <code>WriterAppender</code> will need to override this method. + * Actual writing occurs here. + * <p> + * Most subclasses of <code>WriterAppender</code> will need to override this + * method. * * @since 0.9.0 */ @@ -258,7 +264,10 @@ } try { - writerWrite(this.layout.doLayout(event), this.immediateFlush); + String output = this.layout.doLayout(event); + synchronized (this) { + writerWrite(output, this.immediateFlush); + } } catch (IOException ioe) { // as soon as an exception occurs, move to non-started state // and add a single ErrorStatus to the SM. @@ -266,5 +275,4 @@ addStatus(new ErrorStatus("IO failure in appender", this, ioe)); } } - }