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

48 阅读 0 评论 32 点赞

我是靠谱客的博主默默大炮，最近开发中收集的这篇文章主要介绍[实践]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

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

[参考]

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