logback日志大量写磁盘导致微服务不能正常响应的解决方案

        最近几天，遇到一个莫名其妙的问题，每天几乎同一时段微服务自己跑着跑着就假死了，过几个小时就又自动恢复了。

        通过对定时任务、网卡、内存、磁盘、业务日志的排查分析，只有磁盘的IO在假死前一段时间偏高，经查只要到业务访问高峰时段就会出现磁盘IO偏高的问题。

然后分析日志，也没有明显的异常日志，只是最近业务需求改动比较大，为了方便调试及线上问题排查，增加了不少业务日志。

       然后，通过分析logback.xml的日志配置，日志打印采用的是同步打印appender，配置如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

<springProfile name="gray,prod,console,sandbox">
<property name="MIN_LEVEL" value="INFO" />
<appender name="MAIN-FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 文件路径 -->
    <file>${LOCAL_FILE_PATH}/main.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<!-- 文件名称 -->
    <fileNamePattern>${LOCAL_FILE_PATH}/bak/main.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
    <maxFileSize>2GB</maxFileSize>
    <MaxHistory>15</MaxHistory>
    <totalSizeCap>50GB</totalSizeCap>
</rollingPolicy>
<layout class="ch.qos.logback.classic.PatternLayout">
    <pattern>${PATTERN}</pattern>
</layout>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
    <level>${MIN_LEVEL}</level>
</filter>
</appender>

。。。。。。。。

<logger name="${MYBATIS_SQL_PACKAGE}" level="${MIN_LEVEL}" additivity="false">
    <appender-ref ref="SQL-FILE" />
</logger>
<root level="info">
   <appender-ref ref="MAIN-FILE"/>
  。。。。。。。。。
</root>
</springProfile>     

</configuration> 

通过以上分析，大量的同步的业务日志打印，很可能是微服务短时间假死的源头。

解决方案：

        1、减少不必要的业务日志打印

        2、logback同步日志打印修改成异步日志打印，配置如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

<springProfile name="gray,prod,console,sandbox">
<property name="MIN_LEVEL" value="INFO" />
<appender name="MAIN-FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 文件路径 -->
    <file>${LOCAL_FILE_PATH}/main.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<!-- 文件名称 -->
    <fileNamePattern>${LOCAL_FILE_PATH}/bak/main.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
    <maxFileSize>2GB</maxFileSize>
    <MaxHistory>15</MaxHistory>
    <totalSizeCap>50GB</totalSizeCap>
</rollingPolicy>
<layout class="ch.qos.logback.classic.PatternLayout">
    <pattern>${PATTERN}</pattern>
</layout>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
    <level>${MIN_LEVEL}</level>
</filter>
</appender>

 

<!-- 异步输出 MAIN-FILE-->
<appender name ="ASYNC-MAIN-FILE" class= "ch.qos.logback.classic.AsyncAppender">
    <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
    <discardingThreshold >0</discardingThreshold>
    <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
    <queueSize>512</queueSize>
    <!-- 添加附加的appender,最多只能添加一个 -->
    <appender-ref ref ="MAIN-FILE"/>
    <!-- asyncappender为提高性能，默认关闭打印行号 -->
    <includeCallerData>true</includeCallerData>
</appender>

 

。。。。。。。。

<logger name="${MYBATIS_SQL_PACKAGE}" level="${MIN_LEVEL}" additivity="false">
    <appender-ref ref="SQL-FILE" />
</logger>
<root level="info">
   <appender-ref ref="ASYNC-MAIN-FILE"/>
  。。。。。。。。。。
</root>
</springProfile>     

</configuration> 

             备注：1、asyncappender为提高性能，默认关闭打印行号，若开启的话，需要增加如下配置：<includeCallerData>true</includeCallerData>

                       2、使用AsyncAppender的时候，需要注意的其它先项。由于使用了BlockingQueue来缓存日志，因此就会出现队列满的情况。在这种情况下，AsyncAppender会做出一些处理：默认情况下，如果队列80%已满，AsyncAppender将丢弃TRACE、DEBUG和INFO级别的event，从这点就可以看出，该策略有一个惊人的对event丢失的代价性能的影响。另外其他的一些选项信息，也会对性能产生影响，下面列出常用的几个属性配置信息：

属性名	类型	描述
queueSize	int	BlockingQueue的最大容量，默认情况下，大小为256。
discardingThreshold	int	默认情况下，当BlockingQueue还有20%容量，他将丢弃TRACE、DEBUG和INFO级别的event，只保留WARN和ERROR级别的event。为了保持所有的events，设置该值为0。
includeCallerData	boolean	提取调用者数据的代价是相当昂贵的。为了提升性能，默认情况下，当event被加入到queue时，event关联的调用者数据不会被提取。默认情况下，只有"cheap"的数据，如线程名。