线上事故-logback日志文件过大，导致请求超时

背景项目组内同学遇到一个比较棘手问题，领导让我帮忙看看，某个应用每天00:00~00:05就会出现大量的接口请求超时，导致其他应用调用该系统接口超时情况。并且接口有些几秒甚至几十秒情况发生...

逍遥壮士

3534人浏览 · 2021-12-26 00:45:21

逍遥壮士 · 2021-12-26 00:45:21 发布

背景

项目组内同学遇到一个比较棘手问题，领导让我帮忙看看，某个应用每天00:00~00:05就会出现大量的接口请求超时，导致其他应用调用该系统接口超时情况。并且接口有些几秒甚至几十秒情况发生。

调用方超时情况如下：

排查过程

1.排查超时接口是否有报错？JVM是否配置合理？GC是否正常？是否有慢sql？代码问题等，经过梳理发现没有慢sql、redis正常、注册中心、其他组件一切正常，存在部分代码问题，但是不是主因、JVM也比较正常，并且也做了相应的线程相关的调优，发现问题有所好转，但是依然问题存在。

2.扩容机器，从原先两台扩容到现在六台机器，发现问题依然存在。

3.服务治理，将大部分能迁移不要在00点的服务全部迁移出来，发现问题有所缓解依然存在;（服务治理）

3.调用上方添加缓存，发现调用方超时问题彻底解决，但是接口超时接口问题依然存在！

但是超时接口问题依然存在~

这时就很奇怪了，为什么已经没有timeout的，按道理这么点请求量，有6台机器，经过排查没慢sql 、没死锁、定时任务已迁出、代码也没有重大问题、带宽出网50M、入网5G等等，都不可能导致突然这么慢。引入公司某个注解的确存在一部分慢的原因，但是也不可能导致突然00就慢了，与其他时间点对比，其他时间点的请求量比这个大很多，为什么就不慢？比如下面的早上8点的请求量跟现在差不多，为什么不慢？

问题到底在哪里？？？？？不过经过判断可以断定，问题肯定是应用自身造成的，是由于某些操作突然间就卡住了，而且时间固定在00点。

发现问题点

通过排查日志发现，居然有些日志超过了4G并且都是00点的时候来操作的，非常恐怖，全部统一在00点。而错误排查中发现大量的logback超时情况。

通过运维同学反馈的磁盘情况

通过查询原来的日志文件如下：(注意下面的xx.xx，避免敏感信息暴露，自行替换哈。)

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <springProperty scope="context" name="log_dir" source="log.path"/>
  <property name="maxHistory" value="7" />
  <property name="maxFileSize" value="1GB" />
  <property name="totalSizeCap" value="30GB" />


  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger[%M] - %msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>debug</level>
    </filter>
  </appender>


  <appender name="infofile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/info/info.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}info/info.log.%d{yyyy-MM-dd}</fileNamePattern>
      <maxHistory>${maxHistory}</maxHistory>
      <!--<maxFileSize>${maxFileSize}</maxFileSize>-->
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger[%M] - %msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
  </appender>


  <appender name="errorfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/error/error.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}error/error.log.%d{yyyy-MM-dd}</fileNamePattern>
      <maxHistory>${maxHistory}</maxHistory>
      <!--<maxFileSize>${maxFileSize}</maxFileSize>-->
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger[%M] - %msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>error</level>
    </filter>
  </appender>


  <appender name="accPerLogFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/info/accPerLogFile.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}info/accPerLogFile.log.%d{yyyy-MM-dd}</fileNamePattern>
      <maxHistory>${maxHistory}</maxHistory>
      <!--<maxFileSize>${maxFileSize}</maxFileSize>-->
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger[%M] - %msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
  </appender>


  <logger name="xx.xx.log.aspect.LogAspect" level="info" additivity="false">
    <appender-ref ref="accPerLogFile" />
  </logger>




  <appender name="healthyLog" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/healthyLog/info.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}/healthyLog/info.log.%d{yyyy-MM-dd}</fileNamePattern>
      <maxHistory>${maxHistory}</maxHistory>
      <!--<maxFileSize>${maxFileSize}</maxFileSize>-->
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
  </appender>
  <logger name="xx.xx.log.utils.HealthLogUtil" level="info" additivity="false">
    <appender-ref ref="healthyLog" />
  </logger>


  <logger name="com.alibaba.dubbo.monitor.dubbo" level="off"></logger>
  <logger name="org.springframework.context.support.ResourceBundleMessageSource" level="off"></logger>
  <logger name="xx.xx.ilrms.config" level="off"></logger>
  <logger name="xx.xx.xx" level="info" />


  <root level="info">
    <appender-ref ref="console" />
    <appender-ref ref="infofile" />
    <appender-ref ref="errorfile" />
  </root>
</configuration>

通过原来的日志发现，日志每天晚上00点的时候会自动生成一份隔天的文件备份到路劲：

正常日志：/root/xx-xx-provider/logsinfo

错误日志：/root/xx-xx-provider/logserror

连接请求记录：/root/xx-xx-provider/logs

参数记录：/root/xx-xx-provider/logs/healthyLog

并且以上都是00点自动生成，很有可能就是因为这时候移动日志文件，而日志文件非常大，首先logback，在生成隔天文件的时候，会将当前的log移到指定的位置，然后再新建一个log文件，但是如果在移动的过程中慢，那后续需要打印的日志就需要等待，导致无法响应请求。

查看logback源码：(高版本已解决！)

优化方案

基于以上情况，最新修改如下，

1.将原来每天00点生成隔天文件，改为每200M生成一个文件并且隔天也生成一个文件，每天不限文件次数。

2.原来的每次写入日志操作改为缓存暂时存放，而不是立即写入Log中，以免造成性能低下，线程阻塞。

3.原来日志存放7天，因为已有云平台日志平台收集，改为3天;

4.原来的日志为debug级别改为info级别;

结果看最后演示。

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <springProperty scope="context" name="log_dir" source="log.path"/>
  <property name="maxHistory" value="3" />
  <property name="maxFileSize" value="1GB" />
  <property name="totalSizeCap" value="30GB" />


  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger[%M] - %msg%n</pattern>
      <immediateFlush>false</immediateFlush>
      <charset>UTF-8</charset>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
  </appender>


  <appender name="infofile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/info/info.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}info/info.log.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
      <maxHistory>${maxHistory}</maxHistory>
      <maxFileSize>200MB</maxFileSize>
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%date{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%logger{35}|%thread|[%X{EagleEye-TraceID}]|%X{EAGLEEYE_RPC_ID}|%message%n%exception{full}</pattern>
      <immediateFlush>false</immediateFlush>
      <charset>UTF-8</charset>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
  </appender>


  <appender name="errorfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/error/error.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}error/error.log.%d{yyyy-MM-dd}.%i</fileNamePattern>
      <maxHistory>${maxHistory}</maxHistory>
      <maxFileSize>200MB</maxFileSize>
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
    </rollingPolicy>
    <encoder>
      <pattern>%date{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%logger{35}|%thread|[%X{EagleEye-TraceID}]|%X{EAGLEEYE_RPC_ID}|%message%n%exception{full}</pattern>
      <immediateFlush>false</immediateFlush>
      <charset>UTF-8</charset>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>error</level>
    </filter>
  </appender>


  <!-- 监控大盘 log 文件输出-->
  <appender name="appender-metrics-log" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${log_dir}/metrics.log</file>
    <encoder>
      <pattern>%date{yyyy-MM-dd HH:mm:ss.SSS}|${APP_NAME}|%X{EagleEye-TraceID}|%replace(%message){'\n', '\\n'}%n%nopex</pattern>
      <immediateFlush>false</immediateFlush>
      <charset>UTF-8</charset>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}/metrics.log.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
      <maxHistory>1</maxHistory>
      <maxFileSize>50MB</maxFileSize>
      <totalSizeCap>1GB</totalSizeCap>
    </rollingPolicy>
  </appender>
  <appender name="async-appender-metrics-log" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="appender-metrics-log"/>
    <queueSize>512</queueSize>
    <discardingThreshold>0</discardingThreshold>
    <maxFlushTime>60000</maxFlushTime>
  </appender>
  <logger name="metrics" level="INFO" additivity="false">
    <appender-ref ref="async-appender-metrics-log"/>
  </logger>




  <appender name="accPerLogFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/info/accPerLogFile.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}info/accPerLogFile.log.%d{yyyy-MM-dd}.%i</fileNamePattern>
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
      <maxFileSize>200MB</maxFileSize>
      <maxHistory>${maxHistory}</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>%date{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%logger{35}|%thread|[%X{EagleEye-TraceID}]|%X{EAGLEEYE_RPC_ID}|%message%n%exception{full}</pattern>
      <immediateFlush>false</immediateFlush>
      <charset>UTF-8</charset>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
  </appender>


  <logger name="xx.xx.log.aspect.LogAspect" level="info" additivity="false">
    <appender-ref ref="accPerLogFile" />
  </logger>




  <appender name="healthyLog" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <File>${log_dir}/healthyLog/info.log</File>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>${log_dir}/healthyLog/info.log.%d{yyyy-MM-dd}.%i</fileNamePattern>
      <totalSizeCap>${totalSizeCap}</totalSizeCap>
      <maxFileSize>200MB</maxFileSize>
      <maxHistory>${maxHistory}</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>%msg%n</pattern>
      <immediateFlush>false</immediateFlush>
      <charset>UTF-8</charset>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>info</level>
    </filter>
  </appender>




  <logger name="xx.xx.log.utils.HealthLogUtil" level="info" additivity="false">
    <appender-ref ref="healthyLog" />
  </logger>


  <logger name="com.alibaba.dubbo.monitor.dubbo" level="off"></logger>
  <logger name="org.springframework.context.support.ResourceBundleMessageSource" level="off"></logger>
  <logger name="xx.xx.ilrms.config" level="off"></logger>
  <logger name="xx.xx.xx" level="info" />
  <logger name="xx.xx.log.aspect" level="info"/>
  <logger name="xx.xx.xx.mapper" level="info"/>
  <logger name="com.alibaba.druid.pool.DruidDataSource" level="info"/>


  <root level="info">
    <appender-ref ref="console" />
    <appender-ref ref="infofile" />
    <appender-ref ref="errorfile" />
  </root>
</configuration>

结果如下图：

经过本地和预发、测试环境验证，新的方案在每天00点还是会产生一份隔天备份文件，但是该份文件不会备份所有的数据，仅会备份log最后未满足200M的文件的日志内容。

验证方案

手动将生产环境的日志在23：55分的时候进行迁移命名，如果当00点都不超时的时候，那就应该算验证通过;

/root/xx-xx-provider/logs

error/error.log

info/info.log

info/accPerLogFile.log

java.log

已验证的确由logback生成的日志文件太大，每天00：00：00的时候，logback会生隔天文件，会将原来的文件移动到指定的目录中然后重新创建一个log空文件，但是这个文件太大导致移动期间IO打满，其他的请求等待，导致请求超时。。

最后

突然间接到一个这么紧急的问题，并且对原来系统的架构和相关信息一无了解，的确比较仓促，最要紧是该项目无任何文档，无任何人熟悉....可以说是祖传坑....而且还是一个核心应用，没有日志、不能随便重启、也有发布窗口限制，每周就只有几次发布机会...通过大量排查，耗费大量时间才发现是日志规范问题，所以遵循基本规范真的可以减少大量的坑，希望本文可以分享让大家了解基本排查逻辑。