[实践]Log4j 1.X BufferedIO不工作(<8k时)原因分析, 暨深入探查Java IO Output BufferSize

[介绍]

本人在两年前写过一个关于此标题的总结，先发布于此与君共享。

 

两年前(2013),工作中需要设置log4j 1.x的bufferIO为2048， 但是发现其并没有在达到2048个字节是写入本地文件。而是一直到8k个字节是才写入。设置为其他任何小于8k的值也都没有用。8k好象是一个hardcode value。

因此，我做了一些深入的调查。

 

本文将涉及如下方面

1. log4j bufferIO的使用(code example)

2. log4j bufferIO的限制(1.X), 以及与log4j 2.0的相关区别

3. java BufferWriter的bufferSize的工作方式

4. 操作系统在IO在IO输出方面的基础知识

 

[根本原因]

log4j的bufferIO使用了java 的BufferedWriter. Log4j所设置的bufferSize，即为BufferedWriter的BufferSize.

BufferedWriter底层最终调用为sun.nio.cs.StreamEncode。由于StreamEncode hardcode了8k的buffer，不管底BufferedWriter设置size为多少，其都将数据达到8k时才写入磁盘(flush)。

简单示意如下

Log4j

  |

BufferedWriter

  |

StreamEncode (hardcode 8k buffer)

 

 

[问题引入]

 

Log4j代码示例

1）创建buffered Logger

Logger bufferedLogger = Logger.getLogger("dummy_logger");

bufferedLogger.removeAllAppenders();

bufferedLogger.setLevel(Level.INFO);

 

 

PatternLayout layout = new PatternLayout(PATTERN_LAYOUT);

DailyRollingFileAppenderappender = new DailyRollingFileAppender(layout,logfile,DATE_PATTERN);

 

appender.setBufferSize(bufferSize);

appender.setBufferedIO(true);

 

appender.setThreshold(Level.INFO);

appender.setAppend(true);

appender.activateOptions();

bufferedLogger.addAppender(appender);

2） 调用buffered Logger（bufferSize=2048),每次写入1024字节.观察发现只有写入8次以后，磁盘中才看到log的身影。

Logger bufferedLogger = createBufferedLogger(“1.log”, 2048)’

 

int        sizeEachLog  = 1024;

 

 

for (inti = 0; i < 100; i++)

{

     TimeUnit.SECONDS.sleep(3 );

 

     bufferedLogger. info(

          DummyDataCreator. getDummyString

         ( sizeEachLog,  logSeed  + Integer     

           .toString( i)  + " : "));

 

}

[直接原因]

通过查看OpenSDK源代码(openjdk-6-src-b27-26_oct_2012),得到如下的调用栈

Log4j

  |

BufferedWriter(这里的buffer size只决定这里何时将数据写入到StreamEncode，这里将不进行任何显式flush操作)

  |

sun.nio.cs.StreamEncode (hardcode 8k buffer)

所以说，log4j将buffersize设置为2k，则写入4k以后，bufferwriter将写入4k数据到StreamEncode里面。由于还没有到达StreamEncode的8k的buffersize，数据没有被写入到磁盘/内核中。

 

[深入/扩展]

 

[比较log4j without buffer, log4j with bufferedIO, 和 logj 2.0 bufferedIO]

下表为 1)Log4j 1.X 默认调用输出, 2)log4j 1.X bufferediIO, 3)log4j 2.0 bufferedIO的调用栈。可见log4j2.0没有这个问题，因为它使用了BufferedOutputStream.

1)Log4j – Default	2) Log4j – BufferedIO Enabled	3)Log4j 2.0 – beta6 BufferedIO Enabled
Log4j	Log4j	Log4j
FileOutputStream 备注：在这里，将沿着JNI->JVM->System Call，一直调用到system call的write方法。均为同步调用。	BufferedWritter (configurable buffer)	BufferedOutputSteam (configurable buffer) 备注：当达到指定的buffersize时，就沿着调用关系，一直同步调用到system call.
N/A	sun.nio.cs.StreamEncoder   备注：StreamEncode有hardcode的8k buffer size. 只有数据达到8k的时候,才触发继续JNI->JVN->SYSTEM CALL.	N/A
-------------------------------------------------------- Java Native Interface  -------------------------------------------------------- JVM -------------------------------------------------------- System Call

 

[Java IO(including NIO)（JSK1.6) 在 IO 调用关系中的位置]

 

 

 

IO类型	描述	函数	NOTE
JAVA IO	java IO几乎没有使用C标准IO。只有在ZIP相关功能中使用了C标准IO.	所有Java IO/NIO/NIO2 etc	KB - JVM - IO - hotspot JVM just use Standard IO a little
C标准IO( Standard I/O)	对文件描述符的更高级封装。使用了缓存与流的概念。C库中提供了用户空间的缓存(Higher level abstraction on descriptor. Buffer/Stream concept is used. There is user-space buffers provided by the C library.) fflush()方法调用，会将用户空间缓存flush到内核空间。	fopen/fclose/gets/fgets/puts/fputs/fflush/fseek/etc
内核IO(Kernel I/O | UNIX I/O)	写入到内核后(flush后),虽然还没有sync到磁盘中，通过tail -f还是可以看到文件变化。 内核IO有自己的缓存。(Kernel has its own buffer.)   fsync()方法将刷新内核缓存到设备中	open/close/write/read/flush/seed
设备驱动(Device Driver)	CPU将调用设备驱动程序指令与设备交互( CPU will execute Device Driver instruction to drive the communication with I/O.)

[继续实验]

有兴趣的话，请完成以下实验

实验	参数	期望行为	备注
Java FileOutputStream	无	每次写入都能直接文件中看到变化，即使没有flush。	call kernerl io function. It will reach kernel buffer directly.
Java BufferedOutputSteam	bufsiz-512,  write 256 bytes each time	每次达到buffersize都，都能看到文件内容变化	log4j 2.0 用的就是这个
Java BufferedWriter	bufsiz-512,  write 256 bytes each time	即使达到了512，文件中也看不到。直到8k才看到。	Just the problem of log4j 1.X.
Java FileChannel	direct buffer		it will invoke kernel I/O write directly. [KB - JVM - IO - invokation stack of FileChannel.write()
C Standard IO	bufsiz-512,  write 256 bytes each time	每次达到buffersize都，都能看到文件内容变化	使用setbuf设置buffer大小 there is lib buffer. But it support setup the buffer size.
C Kernel/Unix IO	无	每次写入都能直接文件中看到变化，即使没有fsync。	write to kernel buffer directly

 

 

[环境]

JDK 1.6

 

[参考]

1. HotSpot JVM Source Code http://download.java.net/openjdk/jdk6/
2. Log4j 1.2.17 source code
3. Chapter 13 of <<Operating System>> 9th edition
4. Chapter 12 of <<Computer.Systems.A.Programmer_s.Perspective>> 1st edistion
5. [KB JVM - IO -  call stack of Writer.write()] 
6. [KB JVM - IO -  call stack of OutputSteam.write()] 
7. [KB JVM - IO -  call stack of FileChannel.write()]
8. [KB JDK - how BufferdOutputStream.write() work]
9. [KB JVM - IO -  writing difference between FileOutputstream and BufferedWriter ]
10. [KB JVM - IO - Java IO Reading with call stack - FileInputSteam, RandomAccessFile, and FileChannel]

 

本文从 Buffering_On_JAVA_IO_Write.ppt 重新编排而来