日期:2014-05-17  浏览次数:20835 次

apache log引发io问题

?

目前公司中使用到了apache+jetty/jboss的架构模式,apache承担了日志记录的一个职责。

?

同事在做性能测试时,发现一个奇怪的现象:15个并发直接压apache,load居然达到了100多,tps只有200多。直接压后端的jboss tps可以有1000多。

?

1. 刚开始以为是apache keepalive的搞怪,但后来确认apache配置文件的keepalive模式已经是Off。看了下tcp状态,近1000个close_wait状态(说明是客户端主动关闭,服务端是被动关闭),ESTABLISHED也就20多个.

?

2. 下一步确认apache和后端的jboss链接是否存在异常,通过观察mod_jk的日志文件,ajp协议的tcp链接状态,一切正常,而且链接数也就是80来个,说明到后端的压力并不高。

?

3. 进一步确认apache线程数,发现apache_error.log已经出现Max Client的现象,链接数过多。

?

[Sat Mar 12 17:44:31 2011] [error] server reached MaxClients setting, consider raising the MaxClients setting

?

4. 查了下系统的性能参数(nnd,机器上居然没装sysstat包,sar,iostat命令都用不了),使用vmstat -n 1看了下。 发现cpu 的iowait参数居然达到了60%,基本猜想估计是apache日志记录出了问题

?

5. 检查apache conf文件,使用的log配置。

?

CustomLog "|/usr/alibaba/cronolog/sbin/cronolog /home/ljh/output/logs/cookie_logs/%w/cookie_log" cookie_log 
CustomLog "|/usr/bin/logger -p local1.info" cookie_log 

?

使用了两个CustomLog.

?

  • cronolog?项目使用比较普遍,目前是按周进行cookie访问日志处理,是一个io处理的点。
  • logger系统自带的syslog的接口api。syslog可以支持本地打印和网络打印等。具体的内容可以man logger / ?man syslog
6. 后来确认是syslog引起的问题。
测试环境的redhat版本和线上的测试环境不一致,local1.info在syslog配置中是记录到了/var/log/message本地文件,说白了syslog多走了一次IO。

通过sar命令简单的分析了cronolog和syslog的io tps性能数据.
cronlog:?
cronlog 10并发 20并发 50并发 100并发 
Blk_wrtn/s

3720

?

5077 6621 9394
cpu iowait 1% 1.2% 1.4% 2.2%
request tps 1310 1751 2563 3241

syslog(本地文件 同步输出):
syslog 10并发 20并发 50并发 100并发 
Blk_wrtn/s

1808

1790 1845 1760
cpu iowait 11.9% 12.2% 12.6% 12.4%
request tps 58 50 51 48

syslog(本地文件 异步输出): http://stackoverflow.com/questions/208098/can-syslog-performance-be-improved
syslog 10并发 20并发 50并发 100并发 
Blk_wrtn/s

1235

1624