lizongbo at 618119.com 工作,生活,Android,前端,Linode,Ubuntu,nginx,java,apache,tomcat,Resin,mina,Hessian,XMPP,RPC

2009年02月18日

调整resin的resin.conf优化access-log输出日志

Filed under: Resin — 标签:, — lizongbo @ 00:25

目前服务器上resin.conf的日志配置一般是:
《stdout - path=”/stdout.” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-size=”200mb” /》
《stderr -log path=”log/stderr.log” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-size=”200mb” /》
《access -log path=”logs/access.log” rollover-period=”1D” rollover-size=”200mb”/》

在这种情况下,日志始终是先输出到logs/access.log这样的固定文件里,待文件大小满200M的时候,resin先锁住所有写日志操作,将文件的内容复制到文件名带时间戳的文件里,再清空当前日志文件的内容。
这种情况下,既多增加了磁盘io操作,也因为锁机制导致线程容易满,以至resin被webapp监控重启。
以前出现该问题的时候,只简单的通过关闭access-log绕了过去,而最近web网站的resin也出现了重启,
由于web是lvs负载均衡,因此不能通过关闭accesslog来解决问题。

经过查看resin的源代码分析,结合现在业务的实际情况,可以通过调整日志的配置为按时间周期切割来解决问题。
通过分析和实验,将resin的配置调整后大致为:

《stdout -log path-format=”log/stdout.log.%Y%m%d” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-period=”1D” /》
《stderr -log path-format=”log/stderr.log.%Y%m%d” timestamp=”[%Y-%m-%d %H:%M:%S] ” rollover-period=”1D” /》
《access -log path-format=”logs/access.log.%Y%m%d_%H” rollover-period=”1h”/》
(默认format是combined格式)
上面的是stdout和stderr按天切割(如果代码里异常输出比较多的话,也可以配制成按小时打,例如有:ex.printStackTrace();),access.log按小时切割。

大致分析过程:

访问高峰期时,日志滚动时候,导致线程锁住了。
JMX监控查看线程堆栈可以得知,可以看出大量的线程都 在执行com.caucho.server.log.AccessLog.log的时候BLOCKED了。
[code]
==============================
-tcp-connection-*:80-5973” Id=41812 in BLOCKED on lock=java.lang.Object@14dca59
owned by resin-tcp-connection-*:80-5545 Id=41588
at com.caucho.server.log.AccessLog.log(AccessLog.java:310)
at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:206)
at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:229)
at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:268)
at com.caucho.server.port.TcpConnection.run(TcpConnection.java:389)
at com.caucho.util.ThreadPool.runTasks(ThreadPool.java:507)
at com.caucho.util.ThreadPool.run(ThreadPool.java:433)
at java.lang.Thread.run(Thread.java:619)

[/code]

先下载resin的源代码: http://www.caucho.com/download/resin-3.0.19-src.tar.gz

接下来分析AccessLog的log方法。

可以看到:
if (_isSharedBuffer && ! _isAutoFlush) {
synchronized (_sharedBufferLock) {

而这两个选项的默认值是:_isSharedBuffer=true,_isAutoFlush=false;
(因为resin.conf没有配置对应的属性,例如: shared-buffer=”false” auto-flush=”false”)
而这两个属性在官方文档里并没有直接列出。
http://caucho.com/resin-3.0/config/log.xtp#rollover

(测试了不能设置 auto-flush=”true”,因为没缓冲,还没判断好滚动就直接打到文件了,rollover-size几乎等同失效)

com.caucho.vfs. AbstractRolloverLog.java中:
private static final long DEFAULT_ROLLOVER_CHECK_PERIOD = 600L * 1000L;

private long _rolloverCheckPeriod = DEFAULT_ROLLOVER_CHECK_PERIOD;
滚动日志检测周期默认是10分钟。
而该参数没法在resin.conf中动态配置。

在文件超过指定大小之后,日志滚动的方法为:com.caucho.vfs. AbstractRolloverLog 里的rolloverLog, 这个也是个同步方法:

而执行文件内容的操作是movePathToArchive方法:
而movePathToArchive的做法是:

关键代码是: path.writeToStream(out);和path.truncate()
前一个方法,是表示把当前文件的内容读出来,再写到out里。
后一个方法是,把当前文件内容清空。
而其对应的实现是:
com.caucho.vfs.Path和com.caucho.vfs.FilePath。

从整个代码分析可以得知,resin在按文件大小滚动日志的时候,是检测到当前文件超过200M,就先把缓冲全部写入当前日志文件access.log里,再将access.log的内容读出,再写到 access.log.20090206.1047 这样的文件里,写完之后,再通过truncate利用FileOutputStream的append为false将access.log内容清空。相当于先复制内容到新文件,然后再清空当前文件内容。

而这整个过程中,是同步的,因此在执行复制201M日志的时候,线程全部锁住,而这个时候大量的用户请求正在涌来,导致jmx线程过高且webapp监控告警,于是resin被监控重启。

解决办法:
使用path-format属性替代 path,
例如配置:
《access -log path-format=”logs/access.log.%Y%m%d_%H” rollover-period=”1h”/》
这样就是每小时打一个文件,切换日志输出时候,自动切换,不再产生movePathToArchive操作。
jvm.Log里也没了”Archiving access log to “这样的日志。
Stdout和stderr也是同样处理,有这两个日志的内不会太多,可以配置成按天滚动。
stdout-log元素和stderr-log也有path-format属性。

为什么resin不用File的renameTo通过重命名来切换日志呢,这是因为java的io里,只有所有的流都关闭之后,且操作系统中没有程序对文件持有引用时,文件重命名才能够成功,且renameTo是依赖操作系统的,而这种正在对文件进行读写操作的,执行renameTo无法做到一定成功的。Resin也是因为此,在按文件大小进行滚动的时候,才不得已使用复制文件加清空内容的做法。

一条评论 »

  1. 非常感谢 兄弟也遇到类似的问题 官方也报告了这个BUG http://bugs.caucho.com/view.php?id=3509 官方说的是resin 4.0.0 修复了这个BUG,但没有你分析得这么详细。

    Reply

    评论 by 李 — 2012年09月18日 @ 16:54

RSS feed for comments on this post. TrackBack URL

Leave a comment

Powered by WordPress