数码鹭岛论坛

标题: 调整resin的resin.conf优化access-log输出日志 [打印本页]

作者: 翔子 时间: 2014-11-10 15:58
标题: 调整resin的resin.conf优化access-log输出日志
目前服务器上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也是因为此，在按文件大小进行滚动的时候，才不得已使用复制文件加清空内容的做法。

作者: 翔子 时间: 2014-11-10 16:00
标题: Resin中对日志输出的配置
原文: http://www.javatang.com/archives/2010/11/14/1752494.html

Resin中对日志的设置主要有如下参数：log、logger、access-log、stdout-log和stderr-log。前两个放在<resin>标签，也就是主标签下面，其中log主要用于配置JDK logging API，logger用于指定需要log的包及level，跟log4j中的用法相似，只不过resin中level有个特殊的选项就是off，用于关闭日志输出；而后面三个*-log放在<host>或<host-default>下面，access用于HTTP输出，stdout用于标准输出(System.out)，stderr用于错误输出(System.err，对应log4j中的log.error)。

三个*-log中间的属性是相同的，所以我们集中来说明一下：

path: 用于设定日志文件的路径，非常有意思的是它支持所谓的El Variables and Functions，也就是resin中的变量，比如${host.name}就是虚拟站点的id名称，所以如果将它放在<host-default>下面的话，将path设置为 logs/${host.name}/access.log的话可以将不同站点的日志存放在不同的目录下面。
archive-format: 这个参数可以设置日志归档的格式，如设置为access-%Y%m%d.log可以在归档的时候自动按日期进行归档命名。另外还有一个特性需要说明的是，resin竟然支持自动压缩log文件，而且设置的方法非常简单，只要后缀名是gz就可以了，如access-%Y%m%d.log.gz，这样归档的时候会自动压缩，而且支持windows和linux系统。
format: 用于设置每条日志输出的格式，这个非常简单，而且通常使用系统内置的格式就可以了。
rollover-size: 用来设置归档日志文件的最小尺寸，单位可以设置成kb、mb等等，默认为1mb。
rollover-period: 用来设置归档日志文件的周期，单位可以是1D（一天）、1W(一周)、1M（一个月）等。
最后给出一个范例供大家参考：


<resin xmlns="http://caucho.com/ns/resin"
      xmlns:resin="http://caucho.com/ns/resin/core">

<log name="" level="off" path="stdout:"
      timestamp="[%H:%M:%S.%s] {%{thread}} "/>


<logger name="com.caucho" level="info"/>

<logger name="com.caucho.java" level="config"/>
<logger name="com.caucho.loader" level="config"/>

   <host-default>
   
   <access-log path="logs/${host.name}/access.log"
         archive-format="access-%Y%m%d.log.gz"
         format='%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-Agent}i"'
         rollover-size="10mb"
         rollover-period="1D"/>
   
   <stdout-log path="logs/${host.name}/stdout.log"
         archive-format="stdout-%Y%m%d.log.gz"
         timestamp="[%Y.%m.%d %H:%M:%S.%s]"
         rollover-size="10mb"
         rollover-period="1D"/>
   <stderr-log path="logs/${host.name}/stderr.log"
         archive-format="stderr-%Y%m%d.log.gz"
         timestamp="[%Y.%m.%d %H:%M:%S.%s]"
         rollover-size="10mb"
         rollover-period="1D"/>
   </host-default>
</resin>
最后还有一个事情需要说明一下，如果在windows系统下将resin注册成服务程序之后就会在log目录下产生jvm-defautl.log文件，而且这个文件会一直累加，所以会变的文件非常大而影响resin的性能。原来在Apache和Resin产生大容量日志的解决办法这篇文件中提到的使用httpd -jvm-log NUL的方法在3.1中无法使用，而且查找了大量的文档也没有找到合适的方法，后来索性将log目录中的写入权限去掉了，重启resin也没有任何影响，算是解决了这个问题。

参考资料：

http://caucho.com/resin-3.1/doc/config-log.xtp

http://caucho.com/resin-3.1/doc/el-var.xtp#host

欢迎光临数码鹭岛论坛 (http://www.clore.net/forum/)