一条日志引发的悲剧

  • Z时代
  • 2024-01-10
  • 分类：综合

编程

这几天使用方突然抱怨说接口A比较慢.为了排查这个问题,就有下面有意思的事情.我尽量把和公司相关的业务去掉,抽离出问题模型.

1.查找慢接口

因为我们自己记录每个接口的请求日志,日志里面最重要的一个指标就是RT时间,通过筛选发现不单单接口A有问题,接口B,C,D...等都慢。而且慢的时间有点离谱。拿到这些慢接口的RT时间和请求时间。发现一个规律大部分请求时间都是在 00:00 - 00:05这个五分钟之内发生的。

2.查看APM信息

找到这些慢接口以后,查看这个时间段的APM信息发现,无慢SQL,CPU使用不到30%，堆内存使用正常,Gc日志正常。

3. “大脑宕机了”

有慢接口但各种监控信息都正常。下面就是自我的否定

  • 是否有job？ 和使用方沟通他们一直有job,如果有代码的问题，那么应该早就出现问题了（貌似正确）

  • 是否因为流量太大？因为前面的有负载，请求量都差不多，这条路也没法走下去了

  • CPU,Gc,内存都正常,那线程呢？是否有死锁？线程使用正常，也没找到死锁日志

通过上面的分析，自己没什么思路了，然后就拿着其中一个最慢的接口里面的详细日志,求助网友了，网友给出的意见基本上也是上面分析的，眼看没有有意义的思路，就想放弃的时候，突然发现一个比较诡异的问题，该接口从请求进来到真正执行业务逻辑，居然使用了20s的时间。我马上排查了整个接口的逻辑,突然发现真正执行业务逻辑之前,就是一些对象的基本组装而且真正的业务逻辑执行所耗费的时间都是在毫秒级别.时间都被前面锁花费了，那前面花费到哪里了呢 第一反应就是会不会发生Fgc？但是gc日志在这个时间段上就没有。这是突然一个网友说是否日志本身的问题。看到网友的提醒，突然想到我们的日志会在零点的时候进行滚动

4.排查日志配置

以下是日志配置

<appender name="fileInfo"
             class="ch.qos.logback.core.rolling.RollingFileAppender">
       <file>/data/log/${log.base}/info/info.log</file>
       <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
           <FileNamePattern>/data/log/${log.base}/info/info.%d{yyyy-MM-dd}.log</FileNamePattern>
           <MaxHistory>100</MaxHistory>
       </rollingPolicy>
       <layout class="ch.qos.logback.classic.PatternLayout">
           <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %(${LOG_LEVEL_PATTERN:-%5p}) %logger{256} - %msg%n</pattern>
       </layout>
       <filter class="ch.qos.logback.classic.filter.LevelFilter">
           <level>INFO</level>
           <onMatch>ACCEPT</onMatch>
           <onMismatch>DENY</onMismatch>
       </filter>
   </appender>

通过该配置我们可以看到,每天零点的时候日志会进行滚动,那是不是因为这个问题导致呢,下面我们看下RollingFileAppender的实现,主要看保存日志的代码,具体logback 怎么玩的大家可以自己搜素以下

   //
    @Override
    protected void subAppend(E event) {
        synchronized (triggeringPolicy) {//同步代码
            if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) 
			{ //判断是否需要滚动日志
                rollover();//实现滚动日志的逻辑，看下面的代码
            }
        }
        super.subAppend(event);
    }
//---------下面就是rollover()方法的逻辑，我把英文也贴出来，大家翻译下就知道什么意思了
 public void rollover() {
        lock.lock();
        try {
            // Note: This method needs to be synchronized because it needs exclusive
            // access while it closes and then re-opens the target file.
            //
            // make sure to close the hereto active log file! Renaming under windows
            // does not work for open files.
            this.closeOutputStream();
            attemptRollover();
            attemptOpenFile();
        } finally {
            lock.unlock();
        }
    }

以上代码大概的意思就是，如果需要滚动日志，那么我就需要获取锁，然后关闭当前日志，然后执行滚动日志逻辑。因为在零点的时候需要滚动日志,滚动日志的时候需要加锁。所以在滚动的日志的时候，如果你在接口里面进行了日志打印，例如log.info(xxxx) 那么该条语句就会一直在等待锁直到滚动日志完成以后才能执行.这就导致了在log.info(xx)后的程序被卡住了。等到拿到锁以后再执行业务逻辑,这就是业务逻辑执行花费时间不多,但是接口很慢的原因

5.解决方案

因为是在打印日志的时候阻塞了，那打印日志能不能异步进行呢？答案是可以的 使用AsyncAppender ，具体的用法网上很多，这里就不贴出来了，AsyncAppender就是使用了把打印的日志放到队列里面，然后后台线程去拿队列里面的内容进行打印，即然使用队列那么日志就可能丢失，比如在队列中的日志因为没有及时出队，在机器重启的时候，就会丢失

以上是 一条日志引发的悲剧 的全部内容， 来源链接： utcz.com/z/512159.html

回到顶部