在软件系统中，打日志几乎是每个系统都会使用的行为。不管是用来记录系统健康状态，辅助问题定位，还是收集数据，以便后续数据分析等，日志都起着举足轻重的作用。但是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。为了减少打日志的时间，最主要的是减少往磁盘写日志的次数，但是如果不能从代码层减少写日志的次数，那么考虑从系统上减少往磁盘写日志的次数。

<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();   
           }   
       }   
   } 
}