log4j日志性能优化

       在软件系统中，打日志几乎是每个系统都会使用的行为。不管是用来记录系统健康状态，辅助问题定位，还是收集数据，以便后续数据分析等，日志都起着举足轻重的作用。但是IO的阻塞行为和磁盘的读写速度低下意味着写日志并非是没有代价的。

 

存在问题

          在很多系统中，日志模块用的都是log4j,打日志用的都是同步方法，基本配置如下：

 

<appender name="appAppender" class="org.apache.log4j.DailyRollingFileAppender"> 
        <!-- <param name="Threshold" value="INFO" /> --> 
        <param name="File" value="/data/applogs/XXXXXXXX/logs/app.log"/> 
        <layout class="org.apache.log4j.PatternLayout"> 
            <param name="ConversionPattern" 
                   value="[hotel-order-service]%d [%t] %-5p [%X{HOTEL_LOG_TRACE_ID                          }] [%c %L] %m%n"/> 
        </layout> 
</appender>

 

  按照这种配置，日志的输出行为是，在代码层每次调用输出日志接口的时候，这条日志就马上写入到磁盘中，java的io是阻塞的，而当前磁盘的读写性能低下是共知的。我随机找了公司几台服务器用iostat命令查看了每次写磁盘的时间，发现每次io最快也要1.5ms，慢的需要5.7ms！如果某个接口平均需要打5条日志，那么花在打日志上的时间平均就需要10ms。为了减少打日志的时间，最主要的是减少往磁盘写日志的次数，但是如果不能从代码层减少写日志的次数，那么考虑从系统上减少往磁盘写日志的次数。

 

 

优化方法&测试 

     log4j的DailyRollingFileAppender的实现了缓存模式，即合并日志输出的模式，它先把所有的日志都放到一个buffer数组里，如果buffer满了，就把buffer里内容全部写入磁盘，这样可以大大减少调用磁盘的次数。buffer的大小默认是8K(不同的版本默认值可能不一样)。举个例子， 比如你每次要输出1K的日志，那么你输出8次，才会调用1次磁盘io。为了开启合并日志的方式，需要在配置把bufferedIO设置为true，同时也可以根据系统实际情况设置bufferSize来改变buffer数组的大小。 

      为了验证缓存模式的性能，在某系统中，尝试开启了缓存模式，同时把buffersize设置为50K。下面的配置是开启log4j的缓存：

<appender name="appAppender" class="org.apache.log4j.DailyRollingFileAppender"> 
        <param name="bufferedIO" value="true" />    
         <!-- 50k为一个写单元 ，可以自己定义--> 
        <param name="bufferSize" value="51200" />
        <param name="File" value="/data/applogs/XXXXXXXX/logs/app.log"/> 
        <layout class="org.apache.log4j.PatternLayout"> 
            <param name="ConversionPattern" 
                   value="[hotel-order-service]%d [%t] %-5p [%X{HOTEL_LOG_TRACE_ID}] [%c %L] %m%n"/> 
        </layout> 
</appender>

 

 

          下面是开启缓存模式前后的响应时间测试： 

       首先，需要保证服务器环境的一致性，因为不同的服务以及服务器再不同的qps压力下，响应时间也会不同。因此整个的测试数据收集时间再2个小时以内，从公司内部监控系统来看，测试前后的qps基本一致，保证了测试数据的可靠性。然后对比系统响应时间。系统主要的几个接口响应时间基本降低了10-20ms，同时系统的整体平均响应时间降低了4%。说明了开启缓存模式确实有助于减少系统的响应时间，提升系统的性能。

 

优化日志完整性

       那么问题来了：既然开启缓存模式能提高系统，那么log4j为什么没有默认开启缓存模式呢？个人猜测是因为缓存模式需要缓存填充满了才会写入磁盘，但是假如系统突然崩溃了，缓存中残留的数据没有写入磁盘，从而导致日志丢失。而系统崩溃时的日志往往是排查和定位问题的关键，所以大部分情况下日志的完整性更为重要。但是享受缓慢模式的高性能与日志的完整性真的是鱼与熊掌不可兼得吗？log4j的DailyRollingFileAppender确实不可兼得，但是可以自己扩展DailyRollingFileAppender类。使用jvm钩子，在jvm退出前，先把缓存里的日志写到磁盘上。下面是自己扩展的ExtendDailyRollingFileAppender。 

 

public class ExtendDailyRollingFileAppender extends DailyRollingFileAppender{ 
public ExtendDailyRollingFileAppender() {   
        super();   
        Runtime.getRuntime().addShutdownHook(new Log4jHockThread());   
    } 
public ExtendDailyRollingFileAppender(Layout layout, String filename,   
            String datePattern) throws IOException {   
        super(layout, filename, datePattern);   
        Runtime.getRuntime().addShutdownHook(new Log4jHockThread());   
    } 
public QuietWriter getQw() {   
        return super.qw;   
    }  
private class Log4jHockThread extends Thread {   
       @Override   
       public void run() {   
           QuietWriter qw = ExtendDailyRollingFileAppender.this.getQw();   
           if (qw != null) {   
               qw.flush();   
           }   
       }   
   } 
}