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

调整resin的resin.conf优化access-log输出日志
作者：lizongbo 发表于：00:25. 星期三, 二月 18th, 2009
版权声明：可以任意转载，转载时请务必以超链接形式标明文章原始出处和作者信息及本版权声明。
http://618119.com/archives/2009/02/18/135.html
目前服务器上resin.conf的日志配置一般是：
《stdout -log path=”log/stdout.log” 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了。

==============================
"resin-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)

先下载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也是因为此，在按文件大小进行滚动的时候，才不得已使用复制文件加清空内容的做法。

原文地址：http://618119.com/archives/2009/02/18/135.html