[logback-user] log4j performance comparison

[Ralph Goers]

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 at 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();
>    }

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://qos.ch/pipermail/logback-user/attachments/20110319/40e81b6b/attachment.html>