log4j performance comparison
Hello, based on the old topic archived here for example: http://old.nabble.com/logback-performance-clarification-td9390741.html I performed set of similar tests with debug level actually enabled to see how does logback perform when actually logging. - I noticed slightly worse (than log4j) logback performance in most cases, especially on my Windows machine - I was also interested in the effect of immediateFlush option which was giving us noticable performance improvement with log4j, but was removed from logback as of 0.9.19 (http://logback.qos.ch/manual/appenders.html). Here I noticed that immediateFlush was still giving something (I had to test on logback 0.9.18 in order to compare that). Sad that it was removed. - I've also done some more tests with info level and logback parametrized debug call combined with isDebugEnabled and this one shows typically better performance than plain parametrized debug call as well as classic debug call with isDebugLevel. The main question is - why was immediateFlush removed when it really gives some improvement? Here are some results (all tests performed on Java 1.5 due to its use by the application server we're running at): Windows: log4j 1.2.16, logback 0.9.28 immediateFlush true: ############################################### Log4j direct debug call: 13516 Log4j tested (isDebugEnabled) debug call: 13595 Logback direct debug call: 15593 Logback tested (isDebugEnabled) debug call: 17273 Logback parametrized debug call: 19011 ############################################### Windows: log4j 1.2.16, logback 0.9.18 immediateFlush true: ############################################### Log4j direct debug call: 13421 Log4j tested (isDebugEnabled) debug call: 13240 Logback direct debug call: 15562 Logback tested (isDebugEnabled) debug call: 17112 Logback parametrized debug call: 17981 ############################################### Windows: log4j 1.2.16, logback 0.9.18 immediateFlush false: ############################################### Log4j direct debug call: 6562 Log4j tested (isDebugEnabled) debug call: 6608 Logback direct debug call: 6137 Logback tested (isDebugEnabled) debug call: 7418 Logback parametrized debug call: 8273 ############################################### HP-UX: log4j 1.2.16, logback 0.9.28 immediateFlush true: ############################################### Log4j direct debug call: 17385 Log4j tested (isDebugEnabled) debug call: 17411 Logback direct debug call: 17351 Logback tested (isDebugEnabled) debug call: 17315 Logback parametrized debug call: 17677 ############################################### HP-UX: log4j 1.2.16, logback 0.9.18 immediateFlush true: ############################################### Log4j direct debug call: 17522 Log4j tested (isDebugEnabled) debug call: 17688 Logback direct debug call: 17418 Logback tested (isDebugEnabled) debug call: 17525 Logback parametrized debug call: 17071 ############################################### HP-UX machine: log4j 1.2.16, logback 0.9.18 immediateFlush false: ############################################### Log4j direct debug call: 9936 Log4j tested (isDebugEnabled) debug call: 10869 Logback direct debug call: 9900 Logback tested (isDebugEnabled) debug call: 9907 Logback parametrized debug call: 10346 ############################################### code used for testing ---------------------------------------------------------------------------------------------- package perfTest.ch.qos.logback; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class PerformanceComparator { static Logger logbacklogger = LoggerFactory.getLogger(PerformanceComparator.class); static org.apache.log4j.Logger log4jlogger = org.apache.log4j.Logger.getLogger(PerformanceComparator.class); // How many times should we try to log: static int loop = 1000000; public static void main(String[] args) throws InterruptedException { initConfig(); // Let's run once for Just In Time compiler log4jDirectDebugCall(); log4jTestedDebugCall(); logbackDirectDebugCall(); logbackTestedDebugCall(); logbackParametrizedDebugCall(); // let's run the tests and display the results: long result1 = log4jDirectDebugCall(); long result2 = log4jTestedDebugCall(); long result3 = logbackDirectDebugCall(); long result4 = logbackTestedDebugCall(); long result5 = logbackParametrizedDebugCall(); System.out.println("###############################################"); System.out.println("Log4j direct debug call: " + result1); System.out.println("Log4j tested (isDebugEnabled) debug call: " + result2); System.out.println("Logback direct debug call: " + result3); System.out.println("Logback tested (isDebugEnabled) debug call: " + result4); System.out.println("Logback parametrized debug call: " + result5); System.out.println("###############################################"); } private static long log4jDirectDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { log4jlogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long log4jTestedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (log4jlogger.isDebugEnabled()) { log4jlogger.debug("SEE IF THIS IS LOGGED " + j + "."); } } return (System.nanoTime() - start) / loop; } private static long logbackDirectDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { logbacklogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long logbackTestedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { if (logbacklogger.isDebugEnabled()) logbacklogger.debug("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private static long logbackParametrizedDebugCall() { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { //if (logbacklogger.isDebugEnabled()) //test logbacklogger.debug("SEE IF THIS IS LOGGED {}.", j); } return (System.nanoTime() - start) / loop; } private static void initConfig() { org.apache.log4j.Logger log4jRoot = org.apache.log4j.Logger.getRootLogger(); //log4jRoot.setLevel(org.apache.log4j.Level.INFO); ch.qos.logback.classic.Logger lbRoot = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("ROOT"); //lbRoot.setLevel(ch.qos.logback.classic.Level.INFO); // create the loggers org.apache.log4j.Logger.getLogger("perfTest"); org.apache.log4j.Logger.getLogger("perfTest.ch"); org.apache.log4j.Logger.getLogger("perfTest.ch.qos"); org.apache.log4j.Logger.getLogger("perfTest.ch.qos.logback"); LoggerFactory.getLogger("perfTest"); LoggerFactory.getLogger("perfTest.ch"); LoggerFactory.getLogger("perfTest.ch.qos"); LoggerFactory.getLogger("perfTest.ch.qos.logback"); } } ---------------------------------------------------------------------------------------------- log4j configuration ---------------------------------------------------------------------------------------------- <?xml version="1.0" encoding="UTF-8"?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false"> <appender name="TestLogfile" class="org.apache.log4j.RollingFileAppender"> <param name="File" value="testlog4j.log"/> <param name="MaxFileSize" value="1000KB"/> <param name="maxBackupIndex" value="1"/> <param name="immediateFlush" value="true"/> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%d{ISO8601} %5p [%t] %c{1} %X{transactionId} - %m%n"/> </layout> </appender> <root> <level value="debug"/> <appender-ref ref="TestLogfile"/> </root> </log4j:configuration> ---------------------------------------------------------------------------------------------- logback 0.9.28 configuration ---------------------------------------------------------------------------------------------- <configuration> <appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>testlogback.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <fileNamePattern>testlogback.log.%i</fileNamePattern> <minIndex>1</minIndex> <maxIndex>1</maxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <maxFileSize>1000KB</maxFileSize> </triggeringPolicy> <encoder> <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern> <charset>UTF-8</charset> </encoder> </appender> <root> <level value="debug" /> <appender-ref ref="TestLogfile" /> </root> </configuration> ---------------------------------------------------------------------------------------------- logback 0.9.18 configuration ---------------------------------------------------------------------------------------------- <configuration> <appender name="TestLogfile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <File>testlogback.log</File> <ImmediateFlush>true</ImmediateFlush> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <FileNamePattern>testlogback.log.%i</FileNamePattern> <MinIndex>1</MinIndex> <MaxIndex>1</MaxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <MaxFileSize>1000KB</MaxFileSize> </triggeringPolicy> <Encoding>UTF-8</Encoding> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern> </layout> </appender> <root> <level value="debug" /> <appender-ref ref="TestLogfile" /> </root> </configuration> ----------------------------------------------------------------------------------------------
On 18.03.2011 19:10, hostalp@post.cz wrote:
Hello,
based on the old topic archived here for example: http://old.nabble.com/logback-performance-clarification-td9390741.html
I performed set of similar tests with debug level actually enabled to see how does logback perform when actually logging.
- I noticed slightly worse (than log4j) logback performance in most cases, especially on my Windows machine
- I was also interested in the effect of immediateFlush option which was giving us noticable performance improvement with log4j, but was removed from logback as of 0.9.19 (http://logback.qos.ch/manual/appenders.html). Here I noticed that immediateFlush was still giving something (I had to test on logback 0.9.18 in order to compare that). Sad that it was removed.
- I've also done some more tests with info level and logback parametrized debug call combined with isDebugEnabled and this one shows typically better performance than plain parametrized debug call as well as classic debug call with isDebugLevel.
The main question is - why was immediateFlush removed when it really gives some improvement?
Here are some results (all tests performed on Java 1.5 due to its use by the application server we're running at):
Hello hostalp, The test you mention was designed to measure the performance of disabled log statements. For your test case, you might as well ignore the difference between the direct/isDebugEnabled/parametrized versions. For example, I have simplified the main method to: public static void main(String[] args) throws InterruptedException { // not necessary //initConfig(); // Let's run once for Just In Time compiler log4jDirectDebugCall(); logbackDirectDebugCall(); // let's run the tests and display the results: long result1 = log4jDirectDebugCall(); long result3 = logbackDirectDebugCall(); System.out.println("##########################################"); System.out.println("Smaller is better!"); System.out.println("Log4j direct debug call: " + result1); System.out.println("Logback direct debug call: " + result3); } You should begin your tests using a simple FileAppender instead of a RollingFileAppender with size based triggering. Checking for file size tends to be rather slow and may greatly bias the results. I suggest the following config files: // ========= log4j.xml <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"> <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false"> <appender name="TestLogfile" class="org.apache.log4j.FileAppender"> <param name="File" value="testlog4j.log"/> <param name="immediateFlush" value="false"/> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%d{ISO8601} %5p [%t] %c{1} %X{transactionId} - %m%n"/> </layout> </appender> <root> <level value="debug"/> <appender-ref ref="TestLogfile"/> </root> </log4j:configuration> /// ============ logback.xml <configuration> <appender name="TestLogfile" class="ch.qos.logback.core.FileAppender"> <file>testlogback.log</file> <encoder> <Pattern>%d{ISO8601} %5p [%t] %c{0} %X{transactionId} - %m%n</Pattern> </encoder> </appender> <root level="debug"> <appender-ref ref="TestLogfile" /> </root> </configuration> What are the performance results when you run the above scenario? -- Ceki
Hello, yes You're right the test should be reduced, I left those cases there for curiosity to see how much does the isDebugEnabled check and parametrized logging call affect the results. Your test gives somehing like the following: HP-UX: ############################################### Log4j direct debug call: 7166 Logback direct debug call: 12357 ############################################### Windows: ############################################### Log4j direct debug call: 7122 Logback direct debug call: 17015 ############################################### Which is more or less consistent with previous tests with rolling file appender used. What we're dealing with in multithreaded environment after switching to logback is massive lock contention in the ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) method (seen in the profile data) and generally worse performance which is the reason why we started with some isolated testing.
For multithreaded case I slightly modified the test to run with 100 threads, each producing 10000 log events. The profile data shows high lock contention in method ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) (same as I mentioned in my previous mail) and thread dumps always reveal one runnable thread doing some writing while all other threads are waiting for it. Run times are typically 2-3 times worse than with log4j with immediateFlush=false (6.3-9s vs. 13-20s). So some sort of write batching/buffering really helps in case of heavy activity. "Thread-53" prio=7 tid=00478fa0 nid=67 lwp_id=4143914 runnable [32500000..32500ad0] at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at ch.qos.logback.core.recovery.ResilientOutputStreamBase.write(ResilientOutputStreamBase.java:52) at java.io.OutputStream.write(OutputStream.java:58) at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:103) at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:193) at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:220) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217) - locked <3a84d188> (a java.lang.Object) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:108) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at ch.qos.logback.classic.Logger.debug(Logger.java:534) at perfTest.ch.qos.logback.PerformanceComparator3.logbackDirectDebugCall(PerformanceComparator3.java:63) at perfTest.ch.qos.logback.PerformanceComparator3.access$000(PerformanceComparator3.java:6) at perfTest.ch.qos.logback.PerformanceComparator3$1.run(PerformanceComparator3.java:33) at java.lang.Thread.run(Thread.java:595) "Thread-54" prio=7 tid=00479190 nid=68 lwp_id=4143915 waiting for monitor entry [32440000..32440b50] at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:216) - waiting to lock <3a84d188> (a java.lang.Object) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:108) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at ch.qos.logback.classic.Logger.debug(Logger.java:534) at perfTest.ch.qos.logback.PerformanceComparator3.logbackDirectDebugCall(PerformanceComparator3.java:63) at perfTest.ch.qos.logback.PerformanceComparator3.access$000(PerformanceComparator3.java:6) at perfTest.ch.qos.logback.PerformanceComparator3$1.run(PerformanceComparator3.java:33) at java.lang.Thread.run(Thread.java:595)
On 18/03/2011 10:35 PM, hostalp@post.cz wrote:
For multithreaded case I slightly modified the test to run with 100 threads, each producing 10000 log events. The profile data shows high lock contention in method ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) (same as I mentioned in my previous mail) and thread dumps always reveal one runnable thread doing some writing while all other threads are waiting for it. Run times are typically 2-3 times worse than with log4j with immediateFlush=false (6.3-9s vs. 13-20s). So some sort of write batching/buffering really helps in case of heavy activity.
The last time I checked the performance difference with and without immediate flush the difference was in the order of 10%. It has apparently ballooned to something much more significant. Thank you for bringing this up. -- QOS.ch, main sponsor of cal10n, logback and slf4j open source projects, is looking to hire talented software developers. For further details, see http://logback.qos.ch/job.html
On Mar 18, 2011, at 3:59 PM, Ceki Gülcü wrote:
On 18/03/2011 10:35 PM, hostalp@post.cz wrote:
For multithreaded case I slightly modified the test to run with 100 threads, each producing 10000 log events. The profile data shows high lock contention in method ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) (same as I mentioned in my previous mail) and thread dumps always reveal one runnable thread doing some writing while all other threads are waiting for it. Run times are typically 2-3 times worse than with log4j with immediateFlush=false (6.3-9s vs. 13-20s). So some sort of write batching/buffering really helps in case of heavy activity.
The last time I checked the performance difference with and without immediate flush the difference was in the order of 10%. It has apparently ballooned to something much more significant.
Thank you for bringing this up.
I've spent the whole day testing the provided code on my Mac against Log4j, Logback and my new Log4j 2 code and am getting results that don't seem to make sense. Log4j uses a PrintWriter while Logback uses an OutputStream. Looking at the JDK source code it doesn't look like that should affect things much although I would expect the OutputStream to be slightly faster. So I wrote the test below which got these results that show the FileWriter would seem to be buffered. YourKit would seem to agree as log4j spends almost no time in java.io.FileOutputStream.writeBytes while that is where the majority of the time is spent in Logback. It isn't visible in the Sun source code so I expect the buffering must be happening in sun.nio.cs.StreamEncoder. ############################################### FileOutputStream: 5246 BufferedOutputStream: 854 FileWriter: 882 FileChannel: 9330 ############################################### public class PerformanceComparison { // How many times should we try to log: private static final int COUNT = 1000000; @Test public void testRawPerformance() throws Exception { OutputStream os = new FileOutputStream("target/testos.log", true); long result1 = writeToStream(COUNT, os); os.close(); OutputStream bos = new BufferedOutputStream(new FileOutputStream("target/testbuffer.log", true)); long result2 = writeToStream(COUNT, bos); bos.close(); Writer w = new FileWriter("target/testwriter.log", true); long result3 = writeToWriter(COUNT, w); w.close(); FileOutputStream cos = new FileOutputStream("target/testchannel.log", true); FileChannel channel = cos.getChannel(); long result4 = writeToChannel(COUNT, channel); cos.close(); System.out.println("###############################################"); System.out.println("FileOutputStream: " + result1); System.out.println("BufferedOutputStream: " + result2); System.out.println("FileWriter: " + result3); System.out.println("FileChannel: " + result4); System.out.println("###############################################"); } private long writeToWriter(int loop, Writer w) throws Exception { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { w.write("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; } private long writeToStream(int loop, OutputStream os) throws Exception { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { os.write(getBytes("SEE IF THIS IS LOGGED " + j + ".")); } return (System.nanoTime() - start) / loop; } private long writeToChannel(int loop, FileChannel channel) throws Exception { Integer j = new Integer(2); ByteBuffer buf = ByteBuffer.allocateDirect(8*1024); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { channel.write(getByteBuffer(buf, "SEE IF THIS IS LOGGED " + j + ".")); } return (System.nanoTime() - start) / loop; } private ByteBuffer getByteBuffer(ByteBuffer buf, String s) { buf.clear(); buf.put(s.getBytes()); buf.flip(); return buf; } private byte[] getBytes(String s) { return s.getBytes(); }
Actually, the javadoc for OutputStreamWriter confirms this. http://download.oracle.com/javase/6/docs/api/java/io/OutputStreamWriter.html Ralph On Mar 19, 2011, at 7:40 PM, Ralph Goers wrote:
On Mar 18, 2011, at 3:59 PM, Ceki Gülcü wrote:
On 18/03/2011 10:35 PM, hostalp@post.cz wrote:
For multithreaded case I slightly modified the test to run with 100 threads, each producing 10000 log events. The profile data shows high lock contention in method ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) (same as I mentioned in my previous mail) and thread dumps always reveal one runnable thread doing some writing while all other threads are waiting for it. Run times are typically 2-3 times worse than with log4j with immediateFlush=false (6.3-9s vs. 13-20s). So some sort of write batching/buffering really helps in case of heavy activity.
The last time I checked the performance difference with and without immediate flush the difference was in the order of 10%. It has apparently ballooned to something much more significant.
Thank you for bringing this up.
I've spent the whole day testing the provided code on my Mac against Log4j, Logback and my new Log4j 2 code and am getting results that don't seem to make sense. Log4j uses a PrintWriter while Logback uses an OutputStream. Looking at the JDK source code it doesn't look like that should affect things much although I would expect the OutputStream to be slightly faster. So I wrote the test below which got these results that show the FileWriter would seem to be buffered. YourKit would seem to agree as log4j spends almost no time in java.io.FileOutputStream.writeBytes while that is where the majority of the time is spent in Logback. It isn't visible in the Sun source code so I expect the buffering must be happening in sun.nio.cs.StreamEncoder.
############################################### FileOutputStream: 5246 BufferedOutputStream: 854 FileWriter: 882 FileChannel: 9330 ###############################################
public class PerformanceComparison {
// How many times should we try to log: private static final int COUNT = 1000000;
@Test public void testRawPerformance() throws Exception { OutputStream os = new FileOutputStream("target/testos.log", true); long result1 = writeToStream(COUNT, os); os.close(); OutputStream bos = new BufferedOutputStream(new FileOutputStream("target/testbuffer.log", true)); long result2 = writeToStream(COUNT, bos); bos.close(); Writer w = new FileWriter("target/testwriter.log", true); long result3 = writeToWriter(COUNT, w); w.close(); FileOutputStream cos = new FileOutputStream("target/testchannel.log", true); FileChannel channel = cos.getChannel(); long result4 = writeToChannel(COUNT, channel); cos.close(); System.out.println("###############################################"); System.out.println("FileOutputStream: " + result1); System.out.println("BufferedOutputStream: " + result2); System.out.println("FileWriter: " + result3); System.out.println("FileChannel: " + result4); System.out.println("###############################################"); }
private long writeToWriter(int loop, Writer w) throws Exception { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { w.write("SEE IF THIS IS LOGGED " + j + "."); } return (System.nanoTime() - start) / loop; }
private long writeToStream(int loop, OutputStream os) throws Exception { Integer j = new Integer(2); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { os.write(getBytes("SEE IF THIS IS LOGGED " + j + ".")); } return (System.nanoTime() - start) / loop; }
private long writeToChannel(int loop, FileChannel channel) throws Exception { Integer j = new Integer(2); ByteBuffer buf = ByteBuffer.allocateDirect(8*1024); long start = System.nanoTime(); for (int i = 0; i < loop; i++) { channel.write(getByteBuffer(buf, "SEE IF THIS IS LOGGED " + j + ".")); } return (System.nanoTime() - start) / loop; }
private ByteBuffer getByteBuffer(ByteBuffer buf, String s) { buf.clear(); buf.put(s.getBytes()); buf.flip(); return buf; }
private byte[] getBytes(String s) { return s.getBytes(); }
Yeah, also interesting stuff. And more just for the curiosity - I tried to wrap the FileWriter by BufferedWriter ( http://download.oracle.com/javase/6/docs/api/java/io/BufferedWriter.html ) in your test and to no surprise the result also became very close to BufferedOutputStream. Following results are from 2nd runs within the JVM instance as first runs are (as usually) a little more "biased": Java 6: FileOutputStream: 7186 BufferedOutputStream: 613 FileWriter: 713 BufferedWriter/FileWriter: 625 Java 1.5: FileOutputStream: 7765 BufferedOutputStream: 955 FileWriter: 1131 BufferedWriter/FileWriter: 918 Looks like the use of FileWriter itself is a decent option while adding buffering always helps at least a little. Also funny that BufferedWriter around FileWriter performs consistently better than BufferedOutputStream at Java 1.5 while at Java 6 it's exactly the opposite (but here the difference is minor).
The main takeaway for me is that the default should be to do buffered I/O. Unfortunately, I didn't see an option in Logback to enable buffering at all, much less make it the default. I'm doing that in Log4j2. Doing that cut my overall elapsed time in half. Ralph On Mar 20, 2011, at 9:31 AM, hostalp@post.cz wrote:
Yeah, also interesting stuff. And more just for the curiosity - I tried to wrap the FileWriter by BufferedWriter ( http://download.oracle.com/javase/6/docs/api/java/io/BufferedWriter.html ) in your test and to no surprise the result also became very close to BufferedOutputStream.
Following results are from 2nd runs within the JVM instance as first runs are (as usually) a little more "biased":
Java 6: FileOutputStream: 7186 BufferedOutputStream: 613 FileWriter: 713 BufferedWriter/FileWriter: 625
Java 1.5: FileOutputStream: 7765 BufferedOutputStream: 955 FileWriter: 1131 BufferedWriter/FileWriter: 918
Looks like the use of FileWriter itself is a decent option while adding buffering always helps at least a little. Also funny that BufferedWriter around FileWriter performs consistently better than BufferedOutputStream at Java 1.5 while at Java 6 it's exactly the opposite (but here the difference is minor). _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
Yeah, with few more (and hopefuly last) things to add: Not flushing after every line doesn't seem to make a difference for FileOutputStream in isolated tests (I was getting identical times as with flushing) - unless buffering of course - but it does make difference with logback which uses this FileOutputStream. However logback wraps OutputStreamWriter around it and then it really makes that difference - and also results become very close (almost identical) to FileWriter then. Java 1.5 only: OutputStreamWriter/FileOutputStream immediateFlush: 8435 OutputStreamWriter/FileOutputStream no-flush: 1160 BufferedWriter/OutputStreamWriter/FileOutputStream no-flush: 922 FileWriter immediateFlush: 8271 FileWriter no-flush: 1150 BufferedWriter/FileWriter no-flush: 918 In real logging scenarios it looks to me that immediateFlush=false decreases times to 1/2-1/3 and buffering can give further 10-15% improvement with properly sized buffer. So I definitely vote for bringing at least the immediateFlush=false option back. Bringing back buffering would also be great as one can get a bit more performance out of it - and every little bit does matter for us here. :)
Hi, I guess all the results here are for local files. We log to network file shares over SMB. So I decided to run the PerformanceComparison test from this thread on Windows XP and Java 1.6.0_07 for local and remote files. Here are the results... ############################################### local, FileOutputStream: 7031 local, BufferedOutputStream: 3008 local, FileWriter: 2653 local, FileChannel: 8259 ############################################### ############################################### remote, FileOutputStream: 1618729 remote, BufferedOutputStream: 8743 remote, FileWriter: 8191 remote, FileChannel: 1623684 ############################################### So can we make logback use FileWriter? It seems to be the best for both local and remote files. Also, bizarely, after the test had ran, when I look in the local and remote folders that I was writting to, there were the testbuffer.log and testos.log files, but there was no testchannel.log file? I'm not NIO expert, and the FileOutputStream is being closed, so what's going wrong? David Peter-262 wrote:
Yeah, with few more (and hopefuly last) things to add:
Not flushing after every line doesn't seem to make a difference for FileOutputStream in isolated tests (I was getting identical times as with flushing) - unless buffering of course - but it does make difference with logback which uses this FileOutputStream. However logback wraps OutputStreamWriter around it and then it really makes that difference - and also results become very close (almost identical) to FileWriter then.
Java 1.5 only: OutputStreamWriter/FileOutputStream immediateFlush: 8435 OutputStreamWriter/FileOutputStream no-flush: 1160 BufferedWriter/OutputStreamWriter/FileOutputStream no-flush: 922
FileWriter immediateFlush: 8271 FileWriter no-flush: 1150 BufferedWriter/FileWriter no-flush: 918
In real logging scenarios it looks to me that immediateFlush=false decreases times to 1/2-1/3 and buffering can give further 10-15% improvement with properly sized buffer.
So I definitely vote for bringing at least the immediateFlush=false option back. Bringing back buffering would also be great as one can get a bit more performance out of it - and every little bit does matter for us here. :) _______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user
-- View this message in context: http://old.nabble.com/log4j-performance-comparison-tp31183677p31368496.html Sent from the Logback User mailing list archive at Nabble.com.
participants (5)
-
Ceki Gulcu -
Ceki Gülcü
-
David Roussel -
hostalp＠post.cz -
Ralph Goers