[logback-user] log4j performance comparison

[Ralph Goers]

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