[logback-dev] svn commit: r1968 - in logback/trunk: logback-classic/src/test/java/ch/qos/logback/classic/multiJVM logback-core/src/main/java/ch/qos/logback/core logback-examples/src/main/java/chapter4

noreply.ceki at qos.ch noreply.ceki at qos.ch
Thu Nov 13 18:54:51 CET 2008


Author: ceki
Date: Thu Nov 13 18:54:51 2008
New Revision: 1968

Added:
   logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/
   logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/Checker.java
   logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/LoggingThread.java
   logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/SafeModeFileAppender.java
Modified:
   logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java
   logback/trunk/logback-core/src/main/java/ch/qos/logback/core/WriterAppender.java
   logback/trunk/logback-examples/src/main/java/chapter4/IO.java

Log:
LBCORE-29

Experimental support for multiple JVM's writing to the same file

Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/Checker.java
==============================================================================
--- (empty file)
+++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/Checker.java	Thu Nov 13 18:54:51 2008
@@ -0,0 +1,89 @@
+/**
+ * Logback: the generic, reliable, fast and flexible logging framework.
+ * 
+ * Copyright (C) 2000-2008, 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.multiJVM;
+
+import java.io.BufferedReader;
+import java.io.FileReader;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
+
+public class Checker {
+
+  static long LEN;
+  static String FILENAME;
+
+  static void usage(String msg) {
+    System.err.println(msg);
+    System.err
+        .println("Usage: java "
+            + Checker.class.getName()
+            + " runLength filename stamp0 stamp1 ..\n"
+            + "   runLength (integer) the number of logs to generate perthread\n"
+            + "    filename (string) the filename where to write\n"
+            + "   stamp0 JVM instance stamp0\n"
+            + "   stamp1 JVM instance stamp1\n");
+    System.exit(1);
+  }
+
+  public static void main(String[] argv) throws Exception {
+    if (argv.length < 3) {
+      usage("Wrong number of arguments.");
+    }
+
+    LEN = Integer.parseInt(argv[0]);
+    FILENAME = argv[1];
+
+    for (int i = 2; i < argv.length; i++) {
+      check(argv[i], FILENAME, true);
+    }
+  }
+
+  static void check(String stamp, String filename, boolean safetyMode)
+      throws Exception {
+
+    FileReader fr = new FileReader(FILENAME);
+    BufferedReader br = new BufferedReader(fr);
+
+    String regExp = "^" + stamp + " DEBUG - " + LoggingThread.msgLong
+        + " (\\d+)$";
+    // System.out.println(regExp);
+    Pattern p = Pattern.compile(regExp);
+
+    String line;
+    int expected = 0;
+    while ((line = br.readLine()) != null) {
+      // System.out.println(line);
+      Matcher m = p.matcher(line);
+      if (m.matches()) {
+        String g = m.group(1);
+        int num = Integer.parseInt(g);
+        if (num != expected) {
+          System.err.println("ERROR: out of sequence line: ");
+          System.err.println(line);
+          return;
+        }
+        expected++;
+      }
+    }
+
+    if (expected != LEN) {
+      System.err.println("ERROR: For JVM stamp " + stamp + " found " + expected
+          + " was expecting " + LEN);
+    } else {
+      System.out.println("For JVM stamp " + stamp + " found " + LEN
+          + " lines in correct sequence");
+    }
+    fr.close();
+    br.close();
+
+  }
+
+}

Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/LoggingThread.java
==============================================================================
--- (empty file)
+++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/LoggingThread.java	Thu Nov 13 18:54:51 2008
@@ -0,0 +1,45 @@
+/**
+ * Logback: the generic, reliable, fast and flexible logging framework.
+ * 
+ * Copyright (C) 2000-2008, 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.multiJVM;
+
+import org.slf4j.Logger;
+
+public class LoggingThread extends Thread {
+  static String msgLong = "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA";
+
+  final long len;
+  final Logger logger;
+  private double durationPerLog;
+
+  public LoggingThread(Logger logger, long len) {
+    this.logger = logger;
+    this.len = len;
+  }
+
+  public void run() {
+    long before = System.nanoTime();
+    for (int i = 0; i < len; i++) {
+      logger.debug(msgLong + " " + i);
+//      try {
+//        Thread.sleep(100);
+//      } catch (InterruptedException e) {
+//      }
+    }
+    // in microseconds
+    durationPerLog = (System.nanoTime() - before) / (len * 1000.0);
+  }
+
+  public double getDurationPerLogInMicroseconds() {
+    return durationPerLog;
+  }
+  
+  
+}

Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/SafeModeFileAppender.java
==============================================================================
--- (empty file)
+++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/multiJVM/SafeModeFileAppender.java	Thu Nov 13 18:54:51 2008
@@ -0,0 +1,95 @@
+/**
+ * Logback: the generic, reliable, fast and flexible logging framework.
+ * 
+ * Copyright (C) 2000-2008, 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.multiJVM;
+
+import org.slf4j.Logger;
+
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.PatternLayout;
+import ch.qos.logback.classic.spi.LoggingEvent;
+import ch.qos.logback.core.FileAppender;
+
+/**
+ * An application to write to a file using a FileAppender in safe mode.
+ * 
+ * @author Ceki Gulcu
+ * 
+ */
+public class SafeModeFileAppender {
+
+  static long LEN;
+  static String FILENAME;
+  static String STAMP;
+
+  static public void main(String[] argv) throws Exception {
+    if (argv.length != 3) {
+      usage("Wrong number of arguments.");
+    }
+
+    STAMP = argv[0];
+    LEN = Integer.parseInt(argv[1]);
+    FILENAME = argv[2];
+    writeContinously(STAMP, FILENAME, true);
+  }
+
+  static void usage(String msg) {
+    System.err.println(msg);
+    System.err.println("Usage: java " + SafeModeFileAppender.class.getName()
+        + " stamp runLength filename\n" + " stamp JVM instance stamp\n"
+        + "   runLength (integer) the number of logs to generate perthread"
+        + "    filename (string) the filename where to write\n");
+    System.exit(1);
+  }
+
+  static LoggerContext buildLoggerContext(String stamp, String filename,
+      boolean safetyMode) {
+    LoggerContext loggerContext = new LoggerContext();
+
+    FileAppender<LoggingEvent> fa = new FileAppender<LoggingEvent>();
+
+    PatternLayout patternLayout = new PatternLayout();
+    patternLayout.setPattern(stamp + " %5p - %m%n");
+    patternLayout.setContext(loggerContext);
+    patternLayout.start();
+
+    fa.setLayout(patternLayout);
+    fa.setFile(filename);
+    fa.setAppend(true);
+    fa.setImmediateFlush(true);
+    fa.setBufferedIO(false);
+    fa.setSafeMode(safetyMode);
+    fa.setContext(loggerContext);
+    fa.start();
+
+    ch.qos.logback.classic.Logger root = loggerContext
+        .getLogger(LoggerContext.ROOT_NAME);
+    root.addAppender(fa);
+
+    return loggerContext;
+  }
+
+  static void writeContinously(String stamp, String filename, boolean safetyMode)
+      throws Exception {
+    LoggerContext lc = buildLoggerContext(stamp, filename, safetyMode);
+    Logger logger = lc.getLogger(SafeModeFileAppender.class);
+
+    long before = System.nanoTime();
+    for (int i = 0; i < LEN; i++) {
+      logger.debug(LoggingThread.msgLong + " " + i);
+    }
+    lc.stop();
+    double durationPerLog = (System.nanoTime() - before) / (LEN * 1000.0);
+
+    System.out.println("Average duration of " + (durationPerLog)
+        + " microseconds per log. Safety mode " + safetyMode);
+    System.out.println("------------------------------------------------");
+  }
+}

Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java
==============================================================================
--- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java	(original)
+++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/FileAppender.java	Thu Nov 13 18:54:51 2008
@@ -14,6 +14,8 @@
 import java.io.FileOutputStream;
 import java.io.IOException;
 import java.io.Writer;
+import java.nio.channels.FileChannel;
+import java.nio.channels.FileLock;
 
 import ch.qos.logback.core.status.ErrorStatus;
 import ch.qos.logback.core.status.InfoStatus;
@@ -51,6 +53,10 @@
    */
   protected int bufferSize = 8 * 1024;
 
+  private boolean safeMode = false;
+
+  private FileChannel fileChannel = null;
+
   /**
    * As in most cases, the default constructor does nothing.
    */
@@ -149,7 +155,11 @@
       }
     }
 
-    Writer w = createWriter(new FileOutputStream(fileName, append));
+    FileOutputStream fileOutputStream = new FileOutputStream(fileName, append);
+    if (safeMode) {
+      fileChannel = fileOutputStream.getChannel();
+    }
+    Writer w = createWriter(fileOutputStream);
     if (bufferedIO) {
       w = new BufferedWriter(w, bufferSize);
     }
@@ -172,7 +182,48 @@
     this.bufferSize = bufferSize;
   }
 
+  public String getFileName() {
+    return fileName;
+  }
+
+  public void setFileName(String fileName) {
+    this.fileName = fileName;
+  }
+
+  public boolean isSafeMode() {
+    return safeMode;
+  }
+
+  public void setSafeMode(boolean safeMode) {
+    this.safeMode = safeMode;
+  }
+
   public void setAppend(boolean append) {
     this.append = append;
   }
+
+  @Override
+  protected void writerWrite(String s, boolean flush) throws IOException {
+    if (safeMode && fileChannel != null) {
+      FileLock fileLock = null;
+      try {
+        fileLock = fileChannel.lock();
+        long position = fileChannel.position();
+        long size = fileChannel.size();
+        if(size != position) {
+          //System.out.println("position size mismatch, pos ="+position+" size="+size);
+          fileChannel.position(size);
+        } else {
+          //System.out.println(position+" size="+size);
+        }
+        super.writerWrite(s, true);
+      } finally {
+        if (fileLock != null) {
+          fileLock.release();
+        }
+      }
+    } else {
+      super.writerWrite(s, flush);
+    }
+  }
 }

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	Thu Nov 13 18:54:51 2008
@@ -36,16 +36,14 @@
    * 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;
@@ -71,14 +69,12 @@
    * 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;
@@ -127,8 +123,7 @@
    * 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();
@@ -205,21 +200,17 @@
   void writeHeader() {
     if (layout != null && (this.writer != null)) {
       try {
-
-        String h = layout.getFileHeader();
-        if (h != null) {
-          this.writer.write(h);
-        }
-        String ph = layout.getPresentationHeader();
-        if (ph != null) {
-          this.writer.write(ph);
-        }
-        // If at least one of file header or presentation header were not null, then append a line separator. 
-        // This should be useful in most cases and should not hurt.
-        if ((h != null) || (ph != null)) {
-          this.writer.write(Layout.LINE_SEP);
-          this.writer.flush();
+        StringBuilder sb = new StringBuilder();
+        appendIfNotNull(sb, layout.getFileHeader());
+        appendIfNotNull(sb, layout.getPresentationHeader());
+        if (sb.length() > 0) {
+          sb.append(Layout.LINE_SEP);
+          // If at least one of file header or presentation header were not
+          // null, then append a line separator.
+          // This should be useful in most cases and should not hurt.
+          writerWrite(sb.toString(), true);
         }
+
       } catch (IOException ioe) {
         this.started = false;
         addStatus(new ErrorStatus("Failed to write header for appender named ["
@@ -228,19 +219,21 @@
     }
   }
 
+  private void appendIfNotNull(StringBuilder sb, String s) {
+    if (s != null) {
+      sb.append(s);
+    }
+  }
+
   void writeFooter() {
     if (layout != null && this.writer != null) {
       try {
-        String pf = layout.getPresentationFooter();
-        if (pf != null) {
-          this.writer.write(pf);
-        }
-        String h = layout.getFileFooter();
-        if (h != null) {
-          this.writer.write(h);
+        StringBuilder sb = new StringBuilder();
+        appendIfNotNull(sb, layout.getPresentationFooter());
+        appendIfNotNull(sb, layout.getFileFooter());
+        if (sb.length() > 0) {
+          writerWrite(sb.toString(), true); // force flush
         }
-        // flushing is mandatory if the writer is not later closed.
-        this.writer.flush();
       } catch (IOException ioe) {
         this.started = false;
         addStatus(new ErrorStatus("Failed to write footer for appender named ["
@@ -250,10 +243,9 @@
   }
 
   /**
-   * <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.
@@ -266,11 +258,16 @@
     writeHeader();
   }
 
+  protected void writerWrite(String s, boolean flush) throws IOException {
+    this.writer.write(s);
+    if (flush) {
+      this.writer.flush();
+    }
+  }
+
   /**
-   * 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
    */
@@ -280,10 +277,7 @@
     }
 
     try {
-      this.writer.write(this.layout.doLayout(event));
-      if (this.immediateFlush) {
-        this.writer.flush();
-      }
+      writerWrite(this.layout.doLayout(event), this.immediateFlush);
     } catch (IOException ioe) {
       // as soon as an exception occurs, move to non-started state
       // and add a single ErrorStatus to the SM.

Modified: logback/trunk/logback-examples/src/main/java/chapter4/IO.java
==============================================================================
--- logback/trunk/logback-examples/src/main/java/chapter4/IO.java	(original)
+++ logback/trunk/logback-examples/src/main/java/chapter4/IO.java	Thu Nov 13 18:54:51 2008
@@ -1,7 +1,7 @@
 /**
- * Logback: the reliable, generic, fast and flexible logging framework.
+ * Logback: the generic, reliable, fast and flexible logging framework.
  * 
- * Copyright (C) 1999-2006, QOS.ch
+ * Copyright (C) 2000-2008, 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
@@ -117,7 +117,7 @@
       threads[i].start();
     }
 
-    // wait for them to stop, compute the average throughputs
+    // wait for them to stop, compute the average throughput
     double sum = 0;
 
     for (int i = 0; i < numThreads; i++) {
@@ -131,8 +131,8 @@
       counterThread.join();
     }
 
-    System.out.println("On average throughput of " + (sum / numThreads) +
-      " logs per millisecond.");
+    System.out.println("On average throughput of " + (sum / numThreads)*1000 +
+      " logs per microsecond.");
     System.out.println("------------------------------------------------");
   }
 
@@ -143,16 +143,16 @@
       msg = msgLong;
     }
 
-    long before = System.currentTimeMillis();
+    long before = System.nanoTime();
 
     for (int i = 0; i < len; i++) {
       logger.debug(msg);
     }
 
-    throughput = (len * 1.0) / (System.currentTimeMillis() - before);
+    throughput = (len * 1.0) / (System.nanoTime() - before);
     System.out.println(getName() + ", buffered: " + buffered +
       ", immediateFlush: " + immediateFlush + ", throughput: " + throughput +
-      " logs per millisecond.");
+      " logs per nanosecond.");
   }
 }
 
@@ -162,14 +162,14 @@
   public double counter = 0;
 
   public void run() {
-    long before = System.currentTimeMillis();
+    long before = System.nanoTime();
 
     while (!interrupted) {
-      counter += 0.001;
+      counter += 1.0;
     }
 
-    double tput = (counter * 1.0) / (System.currentTimeMillis() - before);
+    double tput = (counter * 1.0) / (System.nanoTime() - before);
     System.out.println("Counter thread " + getName() +
-      " incremented counter by " + tput + " per millisecond.");
+      " incremented counter by " + tput + " per nanosecond.");
   }
 }


More information about the logback-dev mailing list