接口从4秒到200毫秒-小小的日志竟能引发如此问题

👉 这是一个或许对你有用 的社群

🐱 一对一交流/面试小册/简历优化/求职解惑，欢迎加入 「 芋道快速开发平台 」 知识星球。 下面是星球提供的部分资料：

• 《项目实战（视频）》 ：从书中学，往事中 “练 ”
• 《互联网高频面试题》 ：面朝简历学习，春暖花开
• 《架构 x 系统设计》 ：摧枯拉朽，掌控面试高频场景题
• 《精进 Java 学习指南》 ：系统学习，互联网主流技术栈
• 《必读 Java 源码专栏》 ：知其然，知其所以然

• 1 问题背景
• 2 问题验证
• 3 问题初步定位
• 4 初步思考
• 5 异步日志打印原理
• 6 将日志打印过程中的代码进行逐行注释，找到那一行导致日志输出慢
• 7 结论
• 8 扩展（想了解C底层实现）

1 问题背景

我们的业务需对接不同渠道以完成线上回收业务，然而各渠道皆有其独特的质检标准。为此，我们需对质检标准予以统一化处理，将外部标准转化为内部可识别的质检标准。在此场景下，我们提供了标准映射功能，将外部质检项与内部质检项进行关联。此次问题源于映射关系极为复杂，在导入映射关系后，发现映射逻辑耗时严重，最终定位至日志打印问题。接下来，让我们一同探究如何定位到日志问题以及为何输出大量日志会致使接口变慢。

基于 Spring Boot + MyBatis Plus + Vue & Element 实现的后台管理系统 + 用户小程序，支持 RBAC 动态权限、多租户、数据权限、工作流、三方登录、支付、短信、商城等功能

• 项目地址：https://github.com/YunaiV/ruoyi-vue-pro
• 视频教程：https://doc.iocoder.cn/video/

2 问题验证

在测试环境中维护某渠道质检项与内部质检项映射关系15000+；

发现模版质检转换接口耗时4s左右；

将质检项的映射关系减少到100+时；

模版质检转换接口耗时到了100毫秒左右。

发现模版映射接口时长确实与映射项多少有很强的关联性。

基于 Spring Cloud Alibaba + Gateway + Nacos + RocketMQ + Vue & Element 实现的后台管理系统 + 用户小程序，支持 RBAC 动态权限、多租户、数据权限、工作流、三方登录、支付、短信、商城等功能

• 项目地址：https://github.com/YunaiV/yudao-cloud
• 视频教程：https://doc.iocoder.cn/video/

3 问题初步定位

通过阿里的Arthas工具的trace命令可以分析方法的耗时。

经观察，该方法的耗时主要集中于打印日志。查看代码得知，在将外部质检项映射为内部质检项的过程中会产生大量日志，且映射关系越多，日志数量越多。因项目急于上线，故先对打印日志的代码进行注释，随后发现接口的响应速度明显变快。

4 初步思考

4.1 有没有可能日志打印配置的是同步打印？

首先考虑是否为同步打印日志，毕竟同步读写文件会涉及磁盘随机读写，进而影响效率。经查看 log4j 的配置，得知打印日志的配置为异步打印，而非同步打印。

4.2 既然是异步打印，有没有可能是多线程争抢资源导致打印日志过慢呢？

排除同步打印日志的原因后，由于起初并不了解异步日志打印的底层实现。但依据经验，因需异步打印日志，需有地方存储需要打印的日志，故而可能涉及资源争抢。基于此想法，创建一个测试方法，进行单线程循环打印日志2万次操作。

@Test
private void test4(){
    long l = System.currentTimeMillis();
    for (int i = 0; i 20000; i++) {
      log.info(i+"");
    }
    System.out.println("打印日志耗时：" + (System.currentTimeMillis() - l));
}

发现打印日志耗时为 600 多毫秒。这就感觉很奇怪，如果仅仅存储 20000 个需要打印的日志任务需要这么长时间吗？

于是，搞了一个线程池，提交20000个任务也查看一下耗时；

    public static void main(String[] args) {
        long l = System.currentTimeMillis();
        ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor(10, 10, 60, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<>(20000));
        for (int i = 0; i 20000; i++) {
            threadPoolExecutor.execute(new Runnable() {
                @Override
                public void run() {
                    
                }
            });
        }
        System.out.println("打印耗时：" + (System.currentTimeMillis() - l));
    }

发现只需要2，30毫秒。

在单线程的环境中，若打印大量日志，速度也极为缓慢，由此可见，并非是多线程的问题所致。

我们都清楚，线程池在提交任务时，若队列已满且达到最大线程数，便会执行抛弃策略，其中有一种是将任务交回给提交任务的线程执行。那么在异步日志打印过程中，倘若需打印的日志过多，使得存储需要异步打印日志的地方满了，是否也存在相应的抛弃策略呢？比如将异步打印转为同步打印。所以，我决定先去探究异步打印日志的原理。

5 异步日志打印原理

5.1 Disruptor原理

经过查询资料发现，异步日志打印的底层采用的是Disruptor框架。

其基本原理为生产者向环形数组中存入数据，消费者则消费环形数组中的数据。sequence 用于限制生产者的生产以及消费者的消费。通过阅读代码得知，本质上生产者会保存所有消费者以及自身的 sequence 以限制生产，消费者保存生产者来限制消费。

//org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor#start
public synchronized void start() {
  //....
  //
  disruptor.handleEventsWith(handlers);
  //....
}

//com.lmax.disruptor.dsl.Disruptor#handleEventsWith(com.lmax.disruptor.EventHandler super T>...)
//添加事件处理（消费者）
public final EventHandlerGroup handleEventsWith(final EventHandler super T>... handlers) {
  return createEventProcessors(new Sequence[0], handlers);
}

//com.lmax.disruptor.dsl.Disruptor#createEventProcessors(com.lmax.disruptor.Sequence[], com.lmax.disruptor.EventHandler super T>[])
//创建事件处理（消费对象）
EventHandlerGroup createEventProcessors(
  final Sequence[] barrierSequences,
  final EventHandler super T>[] eventHandlers) {
  //....
  //所有消费者的Sequence
  final Sequence[] processorSequences = new Sequence[eventHandlers.length];
  //将生产者包装成为SequenceBarrier
  final SequenceBarrier barrier = ringBuffer.newBarrier(barrierSequences);
  //遍历事件处理
  for (int i = 0, eventHandlersLength = eventHandlers.length; i     final EventHandler super T> eventHandler = eventHandlers[i];
    //创建事件处理（消费者）
    final BatchEventProcessor batchEventProcessor =
      new BatchEventProcessor<>(ringBuffer, barrier, eventHandler);
    //....
    //将消费者的Sequence放入gatingSequences中
    processorSequences[i] = batchEventProcessor.getSequence();
  }
  //更新生产者的processorSequences
  updateGatingSequencesForNextInChain(barrierSequences, processorSequences);
  //....
}

5.2 异步日志放入Disruptor环形数组的过程

代码

1.将数据放入Disruptor环形数组中

//org.apache.logging.log4j.core.async.AsyncLoggerConfig#logToAsyncDelegate
private void logToAsyncDelegate(final LogEvent event) {
  if (!isFiltered(event)) {
    // Passes on the event to a separate thread that will call
    // asyncCallAppenders(LogEvent).
    populateLazilyInitializedFields(event);
  //尝试将logevnet对象发布到环形数组中
    if (!delegate.tryEnqueue(event, this)) {
      //如果没有放进去，说明队列满了，执行队列满的处理方法，本质上类似于线程池队列满丢弃策略
      //ENQUEUE:将日志放入环形数组（放入不进去就循环等待，一直到放进去）
      //SYNCHRONOUS:当前线程打印日志
      //DISCARD:直接丢弃，忽略日志
      handleQueueFull(event);
    }
  }
}

2.放入环形数组的过程

//org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor#tryEnqueue
public boolean tryEnqueue(final LogEvent event, final AsyncLoggerConfig asyncLoggerConfig) {
    final LogEvent logEvent = prepareEvent(event);
    //获取环形数组
    return disruptor.getRingBuffer().
      //放入环形数组中
      tryPublishEvent(translator, logEvent, asyncLoggerConfig);
}
//com.lmax.disruptor.RingBuffer#tryPublishEvent(com.lmax.disruptor.EventTranslatorTwoArg, A, B)
//尝试放入环形数组中
public  boolean tryPublishEvent(EventTranslatorTwoArg translator, A arg0, B arg1){
    try
    {
      //尝试获取生产者下一个要存放到环形数组中的位置
      final long sequence = sequencer.tryNext();
      //将其放入指定的位置中
      translateAndPublish(translator, sequence, arg0, arg1);
      return true;
    }
    catch (InsufficientCapacityException e)
    {
      //容量不足，就返回fals，执行环形数组满的处理方法
      return false;
    }
}
//com.lmax.disruptor.MultiProducerSequencer#tryNext(int)
//获取生产者下一个位置，n表示当前位置+1，tryNext()就是tryNext(1)
public long tryNext(int n) throws InsufficientCapacityException {
    if (n 1) {
      throw new IllegalArgumentException("n must be > 0");
    }

    long current;
    long next;

    do {
      //获取当前位置
      current = cursor.get();
      //想要获取的位置
      next = current + n;
      //判断是否有可用容量
      //实现原理大概就是比较Sequence（消费者消费到哪里了）和current中的较小值，与next差值是否大于环形数组的大小
      if (!hasAvailableCapacity(gatingSequences, n, current)) {
        throw InsufficientCapacityException.INSTANCE;
      }
    }
    while (!cursor.compareAndSet(current, next));
    return next;
}

发现确实有类似于线程池的抛弃策略。

5.3 复用4.2中打印日志的测试代码进行打断点

经过调试发现，在日志打印的过程中消费者消费快，没有出现 handleQueueFull 的调用。

所以并不会经过ENQUEUE、SYNCHRONOUS、DISCARD的三种策略的处理。

那么现在问题就变得十分离谱，并非上述原因所致。因此，决定采用暴力破解之法，即逐行注释代码的方式，以查看究竟是哪一行代码引发了日志打印缓慢的问题。

6 将日志打印过程中的代码进行逐行注释，找到那一行导致日志输出慢

6.1 定位原因发现是getLocation方法

经过逐行注释后，确定是由于 getLocation 方法所致。那么这行代码究竟有何作用呢？

查询资料得知 getLocation 是用来获取内容匹配日志输出格式中的 %C、%F、%l、%L、%M 。

以下是该方法的调用之处以及其内部代码。

//org.apache.logging.log4j.spi.AbstractLogger#logMessageTrackRecursion
private void logMessageTrackRecursion(final String fqcn,
                                      final Level level,
                                      final Marker marker,
                                      final Message message,
                                      final Throwable throwable) {
  try {
    incrementRecursionDepth(); // LOG4J2-1518, LOG4J2-2031
    tryLogMessage(fqcn, getLocation(fqcn), level, marker, message, throwable);
  } finally {
    decrementRecursionDepth();
  }
}
//org.apache.logging.log4j.spi.AbstractLogger#getLocation
//获取日志是哪个类，哪个方法，哪一行打印的
//举例[11-05 00:03:39 596 INFO ] [] [] [] [main] [] c.z.h.p.r.r.c.ChannelCommonFacadeTest.main(383) - 111
//中的c.z.h.p.r.r.c.ChannelCommonFacadeTest.main(383)字符串
private StackTraceElement getLocation(String fqcn) {
  //requiresLocation 用于判断是否需要Location，不需要直接返回null
  return requiresLocation() ? StackLocatorUtil.calcLocation(fqcn) : null;
}

继续向下追踪会到下方代码

//org.apache.logging.log4j.util.StackLocator#calcLocation
public StackTraceElement calcLocation(final String fqcnOfLogger) {
    //....
   //fqcnOfLogger=org.apache.logging.slf4j.Log4jLogger
    //获取当前方法调用链路上所有的调用链路
    final StackTraceElement[] stackTrace = new Throwable().getStackTrace();
    boolean found = false;
    for (int i = 0; i       final String className = stackTrace[i].getClassName();
      //判断类名称是否相同
      if (fqcnOfLogger.equals(className)) {

        found = true;
        continue;
      }
      //这样就得到了谁调用的日志输出了
      if (found && !fqcnOfLogger.equals(className)) {
        return stackTrace[i];
      }
    }
    return null;
}
//java.lang.Throwable#getStackTrace
public StackTraceElement[] getStackTrace() {
 return getOurStackTrace().clone();
}
//java.lang.Throwable#getOurStackTrace
private synchronized StackTraceElement[] getOurStackTrace() {
  // Initialize stack trace field with information from
  // backtrace if this is the first call to this method
  if (stackTrace == UNASSIGNED_STACK ||
      (stackTrace == null && backtrace != null) /* Out of protocol state */) {
    //获取调用链路的长度
    int depth = getStackTraceDepth();
    stackTrace = new StackTraceElement[depth];
    for (int i=0; i       //获取每一级调用链路
      stackTrace[i] = getStackTraceElement(i);
  } else if (stackTrace == null) {
    return UNASSIGNED_STACK;
  }
  return stackTrace;
}
//方法都是本地方法
native int getStackTraceDepth();
native StackTraceElement getStackTraceElement(int index);

通过上述跟踪源码，怀疑是Java调用C++代码或者需要遍历 StackTraceElement 数组导致异步日志打印过慢。

所以先将 getOurStackTrace 方法进行修改，不调用C++方法，直接创建对象，来排除不是因为遍历数组导致的原因。

//org.apache.logging.log4j.util.StackLocator#calcLocation
public StackTraceElement calcLocation(final String fqcnOfLogger) {
    //....
   //fqcnOfLogger=org.apache.logging.slf4j.Log4jLogger
    //将这里改为自己的写的方法调用，构建方法调用链路
    final StackTraceElement[] stackTrace = stackTraceElements(fqcnOfLogger);
    boolean found = false;
    for (int i = 0; i       final String className = stackTrace[i].getClassName();
      //判断类名称是否相同
      if (fqcnOfLogger.equals(className)) {

        found = true;
        continue;
      }
      //这样就得到了谁调用的日志输出了
      if (found && !fqcnOfLogger.equals(className)) {
        return stackTrace[i];
      }
    }
    return null;
}
/**
* 构建stackTraceElement数组
* @param fqcnOfLogger
* @return
*/
private StackTraceElement[] stackTraceElements(String fqcnOfLogger) {
    //构建一个42长度的，保持测试代码获取相同长度的方法调用链路
    int size = 42;
    StackTraceElement[] stackTraceElement = new StackTraceElement[size];
    for (int i = 0; i 2; i++) {
      stackTraceElement[i] = new StackTraceElement("1", "1", "1", 1);
    }
    stackTraceElement[size - 2] = new StackTraceElement(fqcnOfLogger, "1", "1", 1);
    stackTraceElement[size - 1] = new StackTraceElement("1", "1", "1", 1);
    return stackTraceElement;
}

//然后再执行代码测试代码
@Test
private void test4(){
    long l = System.currentTimeMillis();
    for (int i = 0; i 20000; i++) {
      log.info(i+"");
    }
    System.out.println("打印日志耗时：" + (System.currentTimeMillis() - l));
}

发现耗时只 需要50毫秒 ，所以由此怀疑是Java调用C++代码导致异步日志打印过慢。Java调用C++代码用的框架叫JNI。

6.2 官方资料

这段文字说明使用堆栈跟踪比不实用堆栈跟踪慢30-100倍。

这张图用来说明单线程异步日志记录时需要记录调用位置信息与不需要记录调用位置信息的对比。

6.3 JNI原理

JNI调用Java代码是一种类似反射的原理，先找到jclass、再找到jmethodId，然后调用，这样一步步地来；

Java调用C/C++代码创建对象是需要保存对象指针，然后各种操作是要将指针传入到jni层，然后强转到具体对象再进行操作的。

6.3.1 JNI 架构

JNI 的基本架构可以分为以下几个部分：

• Java 代码 ：调用 native 方法的 Java 类。
• JNI 头文件 ：由 Java 编译器生成的 C/C++ 头文件，定义了 Java 类中的 native 方法。
• 本地实现 ：C/C++ 代码实现 native 方法的具体逻辑。
• Java 虚拟机 ：提供 JNI 支持的运行环境，负责加载和执行 Java 字节码。

6.3.2 数据类型转换

JNI 负责在 Java 数据类型和 C/C++ 数据类型之间进行转换。常见的数据转换方法包括：

• Java 字符串 ：使用 GetStringUTFChars 和 NewStringUTF 方法进行转换。
• Java 数组 ：使用 GetIntArrayElements 、 SetIntArrayRegion 等方法处理数组。