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"的數據，如線程名。