[logback-dev] svn commit: r2310 - in logback/trunk: logback-classic/src/main/java/ch/qos/logback/classic/pattern logback-classic/src/test/java/ch/qos/logback/classic/spi logback-core/src/main/java/ch/qos/logback/core

noreply.ceki at qos.ch noreply.ceki at qos.ch
Mon Jun 29 17:43:52 CEST 2009


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&uuml;lc&uuml;
 

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&uuml;lc&uuml;
  */
-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));
     }
   }
-
 }


More information about the logback-dev mailing list