I would expect performance gains to come from the interleaving of I/O intensive activity with CPU intensive activity; that is, by allowing CPU and I/O to operate asynchronously.
Since this test has nothing but I/O activity I would not expect the test to show a performance improvement at all let alone a significant one. Except for the character-at-a-time versus line-at-a-time direct I/O buffering is generally not performed to speed up file I/O itself but rather to speed up the non-file-io functionality; that is, to keep cpu, or non-io, activity (which is a fast process) from being held up (executed serially) by the I/O activity (which is a slow process). A test such as this that does nothing but I/O activity will fill up a buffer so fast that I would not expect any gain from using a buffer. I would suggest a test that has a significant ratio of CPU to I/O activity. The time to measure is the time taken by the CPU-intensive processes. Without buffering the CPU processes will tend to execute synchronously (in serial with) with the I/O processes. With buffering the CPU processes will tend to execute asynchronously (in parallel with) the I/O processes. -----Original Message----- From: Ceki G�lc� [mailto:[EMAIL PROTECTED]] Sent: Wednesday, June 05, 2002 1: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]>
