专栏首页技术趋势线上事故-logback日志文件过大,导致请求超时

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

背景

项目组内同学遇到一个比较棘手问题,领导让我帮忙看看,某个应用每天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打满,其他的请求等待,导致请求超时。。

最后

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

文章分享自微信公众号:
技术趋势

本文参与 腾讯云自媒体分享计划 ,欢迎热爱写作的你一起参与!

作者:逍遥壮士
原始发表时间:2021-12-26
如有侵权,请联系 cloudcommunity@tencent.com 删除。
登录 后参与评论
0 条评论

相关文章

  • 日志级别动态调整——小工具解决大问题

    背景 随着外卖业务的快速发展,业务复杂度不断增加,线上系统环境有任何细小波动,对整个外卖业务都可能产生巨大的影响,甚至形成灾难性的雪崩效应,造成巨大的经济损失。...

    美团技术团队
  • 案例:Redis命令不当 引起数据库雪崩 造成数百万损失

    最近的互联网线上事故发生比较频繁,9月19日网上爆料出顺丰近期发生了一起线上删库事件,在这里就不介绍了。

    Debian中国
  • Redis的KEYS命令引起宕机事件

    最近的互联网线上事故发生比较频繁,2018年9月19号顺丰发生了一起线上删库事件,在这里就不介绍了。

    Fundebug
  • 这四个问题场景你会排查原因吗?看看高手是如何使用 Arthas 快速定位原因的!

    俗话说的好 “问题排查不用愁,Arthas 来帮您忙。” 今天就来说说这个让妈妈再也不用担心我排查问题的 Java 诊断神器:Arthas!

    程序猿DD
  • 性能测试如何定位瓶颈?偶发超时?看高手如何快速排查问题

    俗话说的好 “问题排查不用愁,Arthas 来帮您忙。” 今天就来说说这个让妈妈再也不用担心我排查问题的 Java 诊断神器——Arthas!

    用户1516716
  • golang 服务诡异499、504网络故障排查

    11-01 12:00 中午午饭期间,手机突然收到业务网关非200异常报警,平时也会有一些少量499或者网络抖动问题触发报警,但是很快就会恢复(目前配置的报警阈...

    王清培
  • 经验分享一箩筐,从此再也不入坑

    多用户并发情况下,CPU 利用率长期为100%,DUMP 线程信息,发现 CPU 利用率高的线程都与 HashMap 操作相关。

    一猿小讲
  • JVM垃圾回收与一次线上内存泄露问题分析和解决过程

    内存泄漏(Memory Leak)是指程序中己动态分配的堆内存由于某种原因程序未释放或无法释放,造成系统内存的浪费,导致程序运行速度减慢甚至系统崩溃等严重后果。

    猿天地
  • 【分布式日志系统】springboot+zipkin+dubbo实现链路跟踪(下)

    提示:可能不同的框架版本会导致有些地方不生效(如sleuth不支持apache版的dubbo),大家在集成的过程中有问题可以私信我,共同探讨。主框架版本如下:s...

    小尘哥
  • golang 服务诡异499、504网络故障排查

    11-01 12:00 中午午饭期间,手机突然收到业务网关非200异常报警,平时也会有一些少量499或者网络抖动问题触发报警,但是很快就会恢复(目前配置的报警阈...

    王清培
  • RPC的超时设置,一不小心就是线上事故

    上面这张监控图,对于服务端的研发同学来说再熟悉不过了。在日常的系统维护中,『服务超时』应该属于监控报警最多的一类问题。

    kunge
  • 浅谈缓冲的理论与实践

    点击上方“芋道源码”,选择“设为星标” 管她前浪,还是后浪? 能浪的浪,才是好浪! 每天 10:33 更新文章,每天掉亿点点头发... 源码精品专栏 原创 |...

    芋道源码
  • 高性能logback

    开发环境一般都把日志输出到ConsoleAppender,但是其他环境是不需要的,可以使用动态配置。

    十毛
  • 记一次JVM FullGC引发严重线上事故的定位、分析、解决过程!

    “ 这篇文章给大家聊一次线上生产系统事故的解决经历,其背后代表的是线上生产系统的JVM FullGC可能引发的严重故障。

    用户1516716
  • Java日志记录最佳实践

    log4j、Logging、commons-logging、slf4j、logback,开发的同学对这几个日志相关的技术不陌生吧,为什么有这么多日志技术,它们都...

    Remember_Ray
  • 一个专业的工程师,从做好日志开始

    在一开始我仅仅对 Node.js 这个技术栈比较感兴趣,但是随着项目的进行,我发现 Node.js 也仅仅是后台服务开发的冰山一角,你需要考虑的更多,需要对很多...

    用户1097444
  • China .NET Conf 2019-.NET技术架构下的混沌工程实践

    这个月的8号、9号,个人很荣幸参加了China.NET Conf 2019 , 中国.NET开发者峰会,同时分享了技术专题《.NET技术架构下的混沌工程实践》,...

    Edison.Ma

扫码关注腾讯云开发者

领取腾讯云代金券