<html><head></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; "><div>Actually, the javadoc for OutputStreamWriter confirms this. <a href="http://download.oracle.com/javase/6/docs/api/java/io/OutputStreamWriter.html">http://download.oracle.com/javase/6/docs/api/java/io/OutputStreamWriter.html</a><br><br>Ralph</div><br><div><div>On Mar 19, 2011, at 7:40 PM, Ralph Goers wrote:</div><br class="Apple-interchange-newline"><blockquote type="cite"><div><br>On Mar 18, 2011, at 3:59 PM, Ceki Gülcü wrote:<br><br><blockquote type="cite">On 18/03/2011 10:35 PM, <a href="mailto:hostalp@post.cz">hostalp@post.cz</a> wrote:<br></blockquote><blockquote type="cite"><blockquote type="cite">For multithreaded case I slightly modified the test to run with 100<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">threads, each producing 10000 log events.<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">The profile data shows high lock contention in method<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(java.lang.Object) (same<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">as I mentioned in my previous mail)<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">and thread dumps always reveal one runnable thread doing some writing<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">while all other threads are waiting for it.<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">Run times are typically 2-3 times worse than with log4j with<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">immediateFlush=false (6.3-9s vs. 13-20s).<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">So some sort of write batching/buffering really helps in case of heavy<br></blockquote></blockquote><blockquote type="cite"><blockquote type="cite">activity.<br></blockquote></blockquote><blockquote type="cite"><br></blockquote><blockquote type="cite">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.<br></blockquote><blockquote type="cite"><br></blockquote><blockquote type="cite">Thank you for bringing this up.<br></blockquote><br>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.<br><br>###############################################<br>FileOutputStream: 5246<br>BufferedOutputStream: 854<br>FileWriter: 882<br>FileChannel: 9330<br>###############################################<br><br><br>public class PerformanceComparison {<br><br> // How many times should we try to log:<br> private static final int COUNT = 1000000;<br><br> @Test<br> public void testRawPerformance() throws Exception {<br> OutputStream os = new FileOutputStream("target/testos.log", true);<br> long result1 = writeToStream(COUNT, os);<br> os.close();<br> OutputStream bos = new BufferedOutputStream(new FileOutputStream("target/testbuffer.log", true));<br> long result2 = writeToStream(COUNT, bos);<br> bos.close();<br> Writer w = new FileWriter("target/testwriter.log", true);<br> long result3 = writeToWriter(COUNT, w);<br> w.close();<br> FileOutputStream cos = new FileOutputStream("target/testchannel.log", true);<br> FileChannel channel = cos.getChannel();<br> long result4 = writeToChannel(COUNT, channel);<br> cos.close();<br> System.out.println("###############################################");<br> System.out.println("FileOutputStream: " + result1);<br> System.out.println("BufferedOutputStream: " + result2);<br> System.out.println("FileWriter: " + result3);<br> System.out.println("FileChannel: " + result4);<br> System.out.println("###############################################");<br> }<br><br> private long writeToWriter(int loop, Writer w) throws Exception {<br> Integer j = new Integer(2);<br> long start = System.nanoTime();<br> for (int i = 0; i < loop; i++) {<br> w.write("SEE IF THIS IS LOGGED " + j + ".");<br> }<br> return (System.nanoTime() - start) / loop;<br> }<br><br> private long writeToStream(int loop, OutputStream os) throws Exception {<br> Integer j = new Integer(2);<br> long start = System.nanoTime();<br> for (int i = 0; i < loop; i++) {<br> os.write(getBytes("SEE IF THIS IS LOGGED " + j + "."));<br> }<br> return (System.nanoTime() - start) / loop;<br> }<br><br> private long writeToChannel(int loop, FileChannel channel) throws Exception {<br> Integer j = new Integer(2);<br> ByteBuffer buf = ByteBuffer.allocateDirect(8*1024);<br> long start = System.nanoTime();<br> for (int i = 0; i < loop; i++) {<br> channel.write(getByteBuffer(buf, "SEE IF THIS IS LOGGED " + j + "."));<br> }<br> return (System.nanoTime() - start) / loop;<br> }<br><br> private ByteBuffer getByteBuffer(ByteBuffer buf, String s) {<br> buf.clear();<br> buf.put(s.getBytes());<br> buf.flip();<br> return buf;<br> }<br><br> private byte[] getBytes(String s) {<br> return s.getBytes();<br> }</div></blockquote></div><br></body></html>