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."); } }