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

1 问题背景

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

2 问题验证

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

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

图片

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

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

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

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<T> 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<T> 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 < eventHandlersLength; i++) {
    final EventHandler<? super T> eventHandler = eventHandlers[i];
    //创建事件处理（消费者）
    final BatchEventProcessor<T> batchEventProcessor =
      new BatchEventProcessor<>(ringBuffer, barrier, eventHandler);
    //....
    //将消费者的Sequence放入gatingSequences中
    processorSequences[i] = batchEventProcessor.getSequence();
  }
  //更新生产者的processorSequences
  updateGatingSequencesForNextInChain(barrierSequences, processorSequences);
  //....
}

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

图片

代码

将数据放入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);
    }
  }
}

放入环形数组的过程

//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<E,A,B>, A, B)
//尝试放入环形数组中
public <A, B> boolean tryPublishEvent(EventTranslatorTwoArg<E, A, B> 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 < stackTrace.length; 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 < depth; 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 < stackTrace.length; 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 < size - 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 等方法处理数组。
Java 对象：使用 GetObjectField、CallObjectMethod 等方法访问对象的字段和方法。

6.3.3 异常处理

JNI 提供异常处理机制，允许本地代码检测和抛出 Java 异常。通过 env->ExceptionCheck() 和 env->Throw 方法，可以在本地代码中检查异常状态并抛出异常。

6.3.4 线程管理

JNI 允许多线程访问 JVM，提供了与线程相关的 API，如 AttachCurrentThread 和 DetachCurrentThread，用于在本地代码中管理 Java 线程。

6.3.5 性能考虑

开销：JNI 方法调用相对 Java 方法调用来说有更高的开销，因为涉及到上下文切换和数据转换。
效率：尽管 JNI 可以提供更高的性能，特别是在需要大量计算或系统级操作时，过多的 JNI 调用可能导致性能下降。

6.4 编写本地方法测试

public class Hello {
    public native int helloFromCpp(int i);

    static {
       //加载动态链接
        System.load(System.getProperty("user.dir") +"/libnative.dylib");
    }
}

下面是如何能进行本地方法调用的过程：

javac Hello.java -h . 将Java文件编译为.class并产生头文件。
产生的头文件的展示

/* DO NOT EDIT THIS FILE - it is machine generated */
#include <jni.h>
/* Header for class test_Hello */

#ifndef _Included_test_Hello
#define _Included_test_Hello
#ifdef __cplusplus
extern "C" {
#endif
/*
 * Class:     test_Hello
 * Method:    helloFromCpp
 * Signature: (I)I
 */
//jni产生的方法名称是有规则的 Java开头 test表示包 Hello表示类 helloFromCpp表示方法
JNIEXPORT jint JNICALL Java_test_Hello_helloFromCpp
  (JNIEnv *, jobject, jint);

#ifdef __cplusplus
}
#endif
#endif

编写头文件对应的cpp文件

/* DO NOT EDIT THIS FILE - it is machine generated */
#include <jni.h>
#include "test_Hello.h"
/* Header for class test_Hello */


/*
 * Class:     test_Hello
 * Method:    helloFromCpp
 * Signature: (I)I
 */
JNIEXPORT jint JNICALL Java_test_Hello_helloFromCpp
  (JNIEnv * env, jobject o , jint j1){
    return j1;
  }

产生动态链接g++ -dynamiclib -o libnative.dylib -I "/Library/Java/JavaVirtualMachines/jdk-1.8.jdk/Contents/Home/include/darwin" -I "/Library/Java/JavaVirtualMachines/jdk-1.8.jdk/Contents/Home/include" test_Hello.cpp
执行代码测试

public static void test() {
  long l = System.currentTimeMillis();
  for (int i = 0; i < 20000*32; i++) {
  Hello h = new Hello();
  h.helloFromCpp(i);
  }
  System.out.println("耗时时间" + (System.currentTimeMillis() - l));
}

注意：苹果电脑要是arm架构的，一定要注意执行Java程序的JDK版本要是arm架构的。

发现耗时很少，所以并不是因为Java通过JNI执行C语言代码的问题。

所以最终结论应该是底层执行C++代码慢的缘故。

7 结论

避免打印过多无用日志，将测试过程中需要观察的日志输出为为 DEBUG 级别。
生产环境打印日志的级别设置为INFO。
如果不需要关注日志打印的位置信息，可以将日志输出格式中的%C、%F、%l、%L、%M去掉。

8 扩展（想了解C底层实现）

可以查看一下下面三个类：

jdk/src/share/native/java/lang/Throwable.c
hotspot/src/share/vm/prims/jvm.cpp
hotspot/src/share/vm/classfile/javaClasses.cpp