最近在系统优化的过程中发现了这么一个情况和大家分享一下。在我公司中间件服务器(Borland BES)上Log4j是这样配置的。

<param name="ImmediateFlush" value="true"/>
<param name="BufferedIO" value="false"/>
<param name="BufferSize" value="8192"/>
<param name="MaxBackupIndex" value="50"/>
<param name="MaxFileSize" value="10MB"/>

然后在系统监控的过程中用发现磁盘IO等待的比较厉害(Linux AS 4.0 for AMD64)的系统,用vmstat 2 20监控如下。


procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 0 160 165024 216328 2698016 0 0 0 19 0 0 1 0 97 2
1 0 160 164816 216328 2698016 0 0 0 64 1280 859 2 0 91 6
0 0 160 164824 216328 2698084 0 0 0 182 1395 961 3 1 84 12
0 1 160 164760 216332 2698148 0 0 0 132 1413 1164 3 1 86 10
0 0 160 164768 216332 2698148 0 0 0 162 1337 842 2 1 88 10
0 1 160 164776 216332 2698148 0 0 0 96 1324 715 2 0 93 5
0 0 160 164784 216332 2698216 0 0 0 804 1218 686 1 1 74 24

其中有几个采样上wa (CPU等待IO的时间)达到了24(一般建议小于10)。这说明由于频繁的写日志(1小时30M左右),导致CPU等待IO时间过长。而且这样频繁的写日志,磁盘也很容易搞坏。

于是对Log4j的配置文件进行了调整,改成了Buffered IO 模式。

<param name="Append" value="true"/>
<param name="ImmediateFlush" value="false"/>
<param name="BufferedIO" value="true"/>
<param name="BufferSize" value="8192"/>

再用vmstat 2 20监控,发现IO明细下降下来了(cs 没有再大于 200过,wa也没有大于20过)


procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 0 160 47016 226124 2790764 0 0 0 20 1 0 1 0 97 2
0 0 160 47032 226124 2790764 0 0 0 194 1377 828 2 1 80 17
0 0 160 47024 226124 2790764 0 0 0 102 1221 1047 3 1 89 8
0 0 160 46952 226124 2790764 0 0 0 84 1269 793 2 1 90 7
0 0 160 46432 226124 2790832 0 0 0 146 1392 1033 4 1 84 10
0 0 160 46432 226124 2790832 0 0 0 110 1346 1189 3 1 86 10
0 0 160 46376 226124 2790832 0 0 0 168 1299 705 2 0 88 10
0 0 160 46320 226124 2790832 0 0 0 36 1413 668 2 0 95 3

对于日志量比较小的应用来说,采用Buffered模式的,对于系统监控和系统管理来说不太方便(特别是用 tail -f 查看的时候),对于日志量比较大的应用来说就需要考虑一下,采用Buffered模式所能够节约的IO了。