My results are: (On PIII 500MHz 256MRam, Win2K, JDK1.3) buffered: false, immediateFlush: true, avg log time: 278.7 in microseconds. buffered: false, immediateFlush: true, avg log time: 282.0 in microseconds. buffered: false, immediateFlush: true, avg log time: 291.71 in microseconds. buffered: false, immediateFlush: true, avg log time: 295.32 in microseconds. buffered: false, immediateFlush: true, avg log time: 296.82 in microseconds. buffered: false, immediateFlush: false, avg log time: 205.3 in microseconds. buffered: false, immediateFlush: false, avg log time: 200.39 in microseconds. buffered: false, immediateFlush: false, avg log time: 207.4 in microseconds. buffered: false, immediateFlush: false, avg log time: 209.41 in microseconds. buffered: false, immediateFlush: false, avg log time: 220.32 in microseconds. buffered: true, immediateFlush: false, avg log time: 235.24 in microseconds. buffered: true, immediateFlush: false, avg log time: 237.95 in microseconds. buffered: true, immediateFlush: false, avg log time: 238.75 in microseconds. buffered: true, immediateFlush: false, avg log time: 239.15 in microseconds. buffered: true, immediateFlush: false, avg log time: 240.25 in microseconds.
Regards Jeroen -----Original Message----- From: Ceki Gülcü [mailto:[EMAIL PROTECTED]] Sent: Wednesday, June 05, 2002 10:07 AM To: [EMAIL PROTECTED] Subject: Buffered IO Hello all, As you probably know, performance of buffered IO is supposed to be much much better then non-buffered IO. In around mid 2001, we had a discussion about buffered IO and although buffered IO is supposedly faster my own tests showed that when outputting logs (write only operation) this was not the case. There were no performance gains that could be observed. Note that all the articles and books discussing buffered IO carry out read-only tests without any writing. So since performance gains could not be verified independently, we did not add buffered IO functionality to log4j. In early 2002, a user (I can't find the name since Bugzilla is down) filed a bug report claiming that on a heavily used server machine adding buffered IO to FileAppender gave a perceptible boost to logging performance. As a response we added buffered IO to FileAppender. The problem is that I sill can't see any 10 fold improvements that some tuning experts assign to buffered IO. Here is a short test file that tests the performance of FileAppender. It uses multiple threads to imitate a "heavily" loaded server. import org.apache.log4j.*; public class IO extends Thread { static String msg = "ABCDEGHIJKLMNOPQRSTUVWXYZabcdeghijklmnopqrstuvwxyz1234567890"; static int BUF_SIZE = 1024*4; public static void main(String argv[]) throws Exception { // What is the length of the runs? long len = Integer.parseInt(argv[0]); boolean buffered; boolean immediateFlush; IO io = null; // first test with unbuffered IO and immediate flushing buffered = false; immediateFlush = true; for(int i = 0; i < 5; i++) { io = new IO(buffered, immediateFlush, len); io.start(); } // join the last created thread. It is likely to be the last // thread to finish, although that is not certain. We wait another // 5 secs just in case. io.join(); Thread.currentThread().sleep(5000); // Second test with unbuffered IO and no immediate flushing buffered = false; immediateFlush = false; for(int i = 0; i < 5; i++) { io = new IO(buffered, immediateFlush, len); io.start(); } io.join(); Thread.currentThread().sleep(5000); // first test with buffered IO and no immediate flushing buffered = true; immediateFlush = false; for(int i = 0; i < 5; i++) { io = new IO(buffered, immediateFlush, len); io.start(); } // There is no fourth test since buffered IO and immediate flushing do not make sense } long len; boolean buffered; boolean immediateFlush; public IO(boolean _buffered, boolean _immediateFlush, long _len) { this.len = _len; this.buffered = _buffered; this.immediateFlush = _immediateFlush; } public void run() { Logger logger = Logger.getLogger("logger-"+getName()); // A FileAppender is created according to the buffering and // immediate flush setting of this IO instance. FileAppender fa = new FileAppender(); fa.setLayout(new PatternLayout("%r %5p %c [%t] - %m%n")); fa.setFile(getName()+".log"); fa.setAppend(false); fa.setImmediateFlush(immediateFlush); fa.setBufferedIO(buffered); fa.setBufferSize(BUF_SIZE); fa.activateOptions(); logger.addAppender(fa); long before = System.currentTimeMillis(); for(int i = 0; i <len; i++) { logger.debug(msg); } double avg = ((System.currentTimeMillis() - before)*1000.0)/len; System.out.println("buffered: "+buffered+", immediateFlush: "+ immediateFlush + ", avg log time: "+avg +" in microseconds."); } } Running the test gives the following results: ~/ > javac IO.java ~/ > java IO 100000 buffered: false, immediateFlush: true, avg log time: 91.94 in microseconds. buffered: false, immediateFlush: true, avg log time: 94.94 in microseconds. buffered: false, immediateFlush: true, avg log time: 97.04 in microseconds. buffered: false, immediateFlush: true, avg log time: 96.44 in microseconds. buffered: false, immediateFlush: true, avg log time: 99.74 in microseconds. buffered: false, immediateFlush: false, avg log time: 67.1 in microseconds. buffered: false, immediateFlush: false, avg log time: 73.21 in microseconds. buffered: false, immediateFlush: false, avg log time: 72.61 in microseconds. buffered: false, immediateFlush: false, avg log time: 74.21 in microseconds. buffered: false, immediateFlush: false, avg log time: 76.11 in microseconds. buffered: true, immediateFlush: false, avg log time: 61.79 in microseconds. buffered: true, immediateFlush: false, avg log time: 63.99 in microseconds. buffered: true, immediateFlush: false, avg log time: 68.1 in microseconds. buffered: true, immediateFlush: false, avg log time: 70.1 in microseconds. buffered: true, immediateFlush: false, avg log time: 71.0 in microseconds. As you can see, immediate flushing has an impact on performance whereas buffering does not. The test was run on Windows (JDK 1.2.2, 1.3.1) and Linux (JDK 1.4.0) with very similar outcomes. Is it possible that the experts are wrong? Could you run the test on other platforms and post the results here? (The whole shebang takes about 5 minutes.) Many thanks in advance, -- Ceki SUICIDE BOMBING - A CRIME AGAINST HUMANITY Sign the petition: http://www.petitiononline.com/1234567b I am signatory number 22106. What is your number? -- To unsubscribe, e-mail: <mailto:[EMAIL PROTECTED]> For additional commands, e-mail: <mailto:[EMAIL PROTECTED]> -- To unsubscribe, e-mail: <mailto:[EMAIL PROTECTED]> For additional commands, e-mail: <mailto:[EMAIL PROTECTED]>
