接口從4秒到200毫秒-小小的日志竟能引發(fā)如此問(wèn)題

作者：陳凱 2024-11-08 15:08:17

1 問(wèn)題背景

我們的業(yè)務(wù)需對(duì)接不同渠道以完成線上回收業(yè)務(wù)，然而各渠道皆有其獨(dú)特的質(zhì)檢標(biāo)準(zhǔn)。為此，我們需對(duì)質(zhì)檢標(biāo)準(zhǔn)予以統(tǒng)一化處理，將外部標(biāo)準(zhǔn)轉(zhuǎn)化為內(nèi)部可識(shí)別的質(zhì)檢標(biāo)準(zhǔn)。在此場(chǎng)景下，我們提供了標(biāo)準(zhǔn)映射功能，將外部質(zhì)檢項(xiàng)與內(nèi)部質(zhì)檢項(xiàng)進(jìn)行關(guān)聯(lián)。此次問(wèn)題源于映射關(guān)系極為復(fù)雜，在導(dǎo)入映射關(guān)系后，發(fā)現(xiàn)映射邏輯耗時(shí)嚴(yán)重，最終定位至日志打印問(wèn)題。接下來(lái)，讓我們一同探究如何定位到日志問(wèn)題以及為何輸出大量日志會(huì)致使接口變慢。

2 問(wèn)題驗(yàn)證

在測(cè)試環(huán)境中維護(hù)某渠道質(zhì)檢項(xiàng)與內(nèi)部質(zhì)檢項(xiàng)映射關(guān)系15000+；

發(fā)現(xiàn)模版質(zhì)檢轉(zhuǎn)換接口耗時(shí)4s左右；

圖片

將質(zhì)檢項(xiàng)的映射關(guān)系減少到100+時(shí)；

模版質(zhì)檢轉(zhuǎn)換接口耗時(shí)到了100毫秒左右。

圖片

發(fā)現(xiàn)模版映射接口時(shí)長(zhǎng)確實(shí)與映射項(xiàng)多少有很強(qiáng)的關(guān)聯(lián)性。

3 問(wèn)題初步定位

通過(guò)阿里的Arthas工具的trace命令可以分析方法的耗時(shí)。

圖片

經(jīng)觀察，該方法的耗時(shí)主要集中于打印日志。查看代碼得知，在將外部質(zhì)檢項(xiàng)映射為內(nèi)部質(zhì)檢項(xiàng)的過(guò)程中會(huì)產(chǎn)生大量日志，且映射關(guān)系越多，日志數(shù)量越多。因項(xiàng)目急于上線，故先對(duì)打印日志的代碼進(jìn)行注釋，隨后發(fā)現(xiàn)接口的響應(yīng)速度明顯變快。

4 初步思考

4.1 有沒(méi)有可能日志打印配置的是同步打印？

首先考慮是否為同步打印日志，畢竟同步讀寫文件會(huì)涉及磁盤隨機(jī)讀寫，進(jìn)而影響效率。經(jīng)查看 log4j 的配置，得知打印日志的配置為異步打印，而非同步打印。

4.2 既然是異步打印，有沒(méi)有可能是多線程爭(zhēng)搶資源導(dǎo)致打印日志過(guò)慢呢？

排除同步打印日志的原因后，由于起初并不了解異步日志打印的底層實(shí)現(xiàn)。但依據(jù)經(jīng)驗(yàn)，因需異步打印日志，需有地方存儲(chǔ)需要打印的日志，故而可能涉及資源爭(zhēng)搶。基于此想法，創(chuàng)建一個(gè)測(cè)試方法，進(jìn)行單線程循環(huán)打印日志2萬(wàn)次操作。

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

發(fā)現(xiàn)打印日志耗時(shí)為 600 多毫秒。這就感覺(jué)很奇怪，如果僅僅存儲(chǔ) 20000 個(gè)需要打印的日志任務(wù)需要這么長(zhǎng)時(shí)間嗎？

于是，搞了一個(gè)線程池，提交20000個(gè)任務(wù)也查看一下耗時(shí)；

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("打印耗時(shí)：" + (System.currentTimeMillis() - l));
    }

發(fā)現(xiàn)只需要2，30毫秒。

在單線程的環(huán)境中，若打印大量日志，速度也極為緩慢，由此可見，并非是多線程的問(wèn)題所致。

我們都清楚，線程池在提交任務(wù)時(shí)，若隊(duì)列已滿且達(dá)到最大線程數(shù)，便會(huì)執(zhí)行拋棄策略，其中有一種是將任務(wù)交回給提交任務(wù)的線程執(zhí)行。那么在異步日志打印過(guò)程中，倘若需打印的日志過(guò)多，使得存儲(chǔ)需要異步打印日志的地方滿了，是否也存在相應(yīng)的拋棄策略呢？比如將異步打印轉(zhuǎn)為同步打印。所以，我決定先去探究異步打印日志的原理。

5 異步日志打印原理

5.1 Disruptor原理

經(jīng)過(guò)查詢資料發(fā)現(xiàn)，異步日志打印的底層采用的是Disruptor框架。

圖片

其基本原理為生產(chǎn)者向環(huán)形數(shù)組中存入數(shù)據(jù)，消費(fèi)者則消費(fèi)環(huán)形數(shù)組中的數(shù)據(jù)。sequence 用于限制生產(chǎn)者的生產(chǎn)以及消費(fèi)者的消費(fèi)。通過(guò)閱讀代碼得知，本質(zhì)上生產(chǎn)者會(huì)保存所有消費(fèi)者以及自身的 sequence 以限制生產(chǎn)，消費(fèi)者保存生產(chǎn)者來(lái)限制消費(fèi)。

//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>...)
//添加事件處理（消費(fèi)者）
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>[])
//創(chuàng)建事件處理（消費(fèi)對(duì)象）
EventHandlerGroup<T> createEventProcessors(
  final Sequence[] barrierSequences,
  final EventHandler<? super T>[] eventHandlers) {
  //....
  //所有消費(fèi)者的Sequence
  final Sequence[] processorSequences = new Sequence[eventHandlers.length];
  //將生產(chǎn)者包裝成為SequenceBarrier
  final SequenceBarrier barrier = ringBuffer.newBarrier(barrierSequences);
  //遍歷事件處理
  for (int i = 0, eventHandlersLength = eventHandlers.length; i < eventHandlersLength; i++) {
    final EventHandler<? super T> eventHandler = eventHandlers[i];
    //創(chuàng)建事件處理（消費(fèi)者）
    final BatchEventProcessor<T> batchEventProcessor =
      new BatchEventProcessor<>(ringBuffer, barrier, eventHandler);
    //....
    //將消費(fèi)者的Sequence放入gatingSequences中
    processorSequences[i] = batchEventProcessor.getSequence();
  }
  //更新生產(chǎn)者的processorSequences
  updateGatingSequencesForNextInChain(barrierSequences, processorSequences);
  //....
}

5.2 異步日志放入Disruptor環(huán)形數(shù)組的過(guò)程

圖片

代碼

將數(shù)據(jù)放入Disruptor環(huán)形數(shù)組中

//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對(duì)象發(fā)布到環(huán)形數(shù)組中
    if (!delegate.tryEnqueue(event, this)) {
      //如果沒(méi)有放進(jìn)去，說(shuō)明隊(duì)列滿了，執(zhí)行隊(duì)列滿的處理方法，本質(zhì)上類似于線程池隊(duì)列滿丟棄策略
      //ENQUEUE:將日志放入環(huán)形數(shù)組（放入不進(jìn)去就循環(huán)等待，一直到放進(jìn)去）
      //SYNCHRONOUS:當(dāng)前線程打印日志
      //DISCARD:直接丟棄，忽略日志
      handleQueueFull(event);
    }
  }
}

放入環(huán)形數(shù)組的過(guò)程

//org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor#tryEnqueue
public boolean tryEnqueue(final LogEvent event, final AsyncLoggerConfig asyncLoggerConfig) {
    final LogEvent logEvent = prepareEvent(event);
    //獲取環(huán)形數(shù)組
    return disruptor.getRingBuffer().
      //放入環(huán)形數(shù)組中
      tryPublishEvent(translator, logEvent, asyncLoggerConfig);
}
//com.lmax.disruptor.RingBuffer#tryPublishEvent(com.lmax.disruptor.EventTranslatorTwoArg<E,A,B>, A, B)
//嘗試放入環(huán)形數(shù)組中
public <A, B> boolean tryPublishEvent(EventTranslatorTwoArg<E, A, B> translator, A arg0, B arg1){
    try
    {
      //嘗試獲取生產(chǎn)者下一個(gè)要存放到環(huán)形數(shù)組中的位置
      final long sequence = sequencer.tryNext();
      //將其放入指定的位置中
      translateAndPublish(translator, sequence, arg0, arg1);
      return true;
    }
    catch (InsufficientCapacityException e)
    {
      //容量不足，就返回fals，執(zhí)行環(huán)形數(shù)組滿的處理方法
      return false;
    }
}
//com.lmax.disruptor.MultiProducerSequencer#tryNext(int)
//獲取生產(chǎn)者下一個(gè)位置，n表示當(dāng)前位置+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 {
      //獲取當(dāng)前位置
      current = cursor.get();
      //想要獲取的位置
      next = current + n;
      //判斷是否有可用容量
      //實(shí)現(xiàn)原理大概就是比較Sequence（消費(fèi)者消費(fèi)到哪里了）和current中的較小值，與next差值是否大于環(huán)形數(shù)組的大小
      if (!hasAvailableCapacity(gatingSequences, n, current)) {
        throw InsufficientCapacityException.INSTANCE;
      }
    }
    while (!cursor.compareAndSet(current, next));
    return next;
}

發(fā)現(xiàn)確實(shí)有類似于線程池的拋棄策略。

5.3 復(fù)用4.2中打印日志的測(cè)試代碼進(jìn)行打斷點(diǎn)

經(jīng)過(guò)調(diào)試發(fā)現(xiàn)，在日志打印的過(guò)程中消費(fèi)者消費(fèi)快，沒(méi)有出現(xiàn)handleQueueFull的調(diào)用。

所以并不會(huì)經(jīng)過(guò)ENQUEUE、SYNCHRONOUS、DISCARD的三種策略的處理。

那么現(xiàn)在問(wèn)題就變得十分離譜，并非上述原因所致。因此，決定采用暴力破解之法，即逐行注釋代碼的方式，以查看究竟是哪一行代碼引發(fā)了日志打印緩慢的問(wèn)題。

6 將日志打印過(guò)程中的代碼進(jìn)行逐行注釋，找到那一行導(dǎo)致日志輸出慢

6.1 定位原因發(fā)現(xiàn)是getLocation方法

經(jīng)過(guò)逐行注釋后，確定是由于getLocation方法所致。那么這行代碼究竟有何作用呢？

查詢資料得知getLocation 是用來(lái)獲取內(nèi)容匹配日志輸出格式中的%C、%F、%l、%L、%M 。

以下是該方法的調(diào)用之處以及其內(nèi)部代碼。

//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
//獲取日志是哪個(gè)類，哪個(gè)方法，哪一行打印的
//舉例[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;
}

繼續(xù)向下追蹤會(huì)到下方代碼：

//org.apache.logging.log4j.util.StackLocator#calcLocation
public StackTraceElement calcLocation(final String fqcnOfLogger) {
    //....
   //fqcnOfLogger=org.apache.logging.slf4j.Log4jLogger
    //獲取當(dāng)前方法調(diào)用鏈路上所有的調(diào)用鏈路
    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;
      }
      //這樣就得到了誰(shuí)調(diào)用的日志輸出了
      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 */) {
    //獲取調(diào)用鏈路的長(zhǎng)度
    int depth = getStackTraceDepth();
    stackTrace = new StackTraceElement[depth];
    for (int i=0; i < depth; i++)
      //獲取每一級(jí)調(diào)用鏈路
      stackTrace[i] = getStackTraceElement(i);
  } else if (stackTrace == null) {
    return UNASSIGNED_STACK;
  }
  return stackTrace;
}
//方法都是本地方法
native int getStackTraceDepth();
native StackTraceElement getStackTraceElement(int index);

通過(guò)上述跟蹤源碼，懷疑是Java調(diào)用C++代碼或者需要遍歷StackTraceElement數(shù)組導(dǎo)致異步日志打印過(guò)慢。

所以先將getOurStackTrace方法進(jìn)行修改，不調(diào)用C++方法，直接創(chuàng)建對(duì)象，來(lái)排除不是因?yàn)楸闅v數(shù)組導(dǎo)致的原因。

//org.apache.logging.log4j.util.StackLocator#calcLocation
public StackTraceElement calcLocation(final String fqcnOfLogger) {
    //....
   //fqcnOfLogger=org.apache.logging.slf4j.Log4jLogger
    //將這里改為自己的寫的方法調(diào)用，構(gòu)建方法調(diào)用鏈路
    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;
      }
      //這樣就得到了誰(shuí)調(diào)用的日志輸出了
      if (found && !fqcnOfLogger.equals(className)) {
        return stackTrace[i];
      }
    }
    return null;
}
/**
* 構(gòu)建stackTraceElement數(shù)組
* @param fqcnOfLogger
* @return
*/
private StackTraceElement[] stackTraceElements(String fqcnOfLogger) {
    //構(gòu)建一個(gè)42長(zhǎng)度的，保持測(cè)試代碼獲取相同長(zhǎng)度的方法調(diào)用鏈路
    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;
}

//然后再執(zhí)行代碼測(cè)試代碼
@Test
private void test4(){
    long l = System.currentTimeMillis();
    for (int i = 0; i < 20000; i++) {
      log.info(i+"");
    }
    System.out.println("打印日志耗時(shí)：" + (System.currentTimeMillis() - l));
}

發(fā)現(xiàn)耗時(shí)只需要50毫秒，所以由此懷疑是Java調(diào)用C++代碼導(dǎo)致異步日志打印過(guò)慢。Java調(diào)用C++代碼用的框架叫JNI。

6.2 官方資料

圖片

這段文字說(shuō)明使用堆棧跟蹤比不實(shí)用堆棧跟蹤慢30-100倍。

圖片

這張圖用來(lái)說(shuō)明單線程異步日志記錄時(shí)需要記錄調(diào)用位置信息與不需要記錄調(diào)用位置信息的對(duì)比。

6.3 JNI原理

JNI調(diào)用Java代碼是一種類似反射的原理，先找到j(luò)class、再找到j(luò)methodId，然后調(diào)用，這樣一步步地來(lái)；

Java調(diào)用C/C++代碼創(chuàng)建對(duì)象是需要保存對(duì)象指針，然后各種操作是要將指針傳入到j(luò)ni層，然后強(qiáng)轉(zhuǎn)到具體對(duì)象再進(jìn)行操作的。

6.3.1 JNI 架構(gòu)

JNI 的基本架構(gòu)可以分為以下幾個(gè)部分：

Java 代碼：調(diào)用 native 方法的 Java 類。
JNI 頭文件：由 Java 編譯器生成的 C/C++ 頭文件，定義了 Java 類中的 native 方法。
本地實(shí)現(xiàn)：C/C++ 代碼實(shí)現(xiàn) native 方法的具體邏輯。
Java 虛擬機(jī)：提供 JNI 支持的運(yùn)行環(huán)境，負(fù)責(zé)加載和執(zhí)行 Java 字節(jié)碼。

6.3.2 數(shù)據(jù)類型轉(zhuǎn)換

JNI 負(fù)責(zé)在 Java 數(shù)據(jù)類型和 C/C++ 數(shù)據(jù)類型之間進(jìn)行轉(zhuǎn)換。常見的數(shù)據(jù)轉(zhuǎn)換方法包括：

Java 字符串：使用 GetStringUTFChars 和 NewStringUTF 方法進(jìn)行轉(zhuǎn)換。
Java 數(shù)組：使用 GetIntArrayElements、SetIntArrayRegion 等方法處理數(shù)組。
Java 對(duì)象：使用 GetObjectField、CallObjectMethod 等方法訪問(wèn)對(duì)象的字段和方法。

6.3.3 異常處理

JNI 提供異常處理機(jī)制，允許本地代碼檢測(cè)和拋出 Java 異常。通過(guò) env->ExceptionCheck() 和 env->Throw 方法，可以在本地代碼中檢查異常狀態(tài)并拋出異常。

6.3.4 線程管理

JNI 允許多線程訪問(wèn) JVM，提供了與線程相關(guān)的 API，如 AttachCurrentThread 和 DetachCurrentThread，用于在本地代碼中管理 Java 線程。

6.3.5 性能考慮

開銷：JNI 方法調(diào)用相對(duì) Java 方法調(diào)用來(lái)說(shuō)有更高的開銷，因?yàn)樯婕暗缴舷挛那袚Q和數(shù)據(jù)轉(zhuǎn)換。
效率：盡管 JNI 可以提供更高的性能，特別是在需要大量計(jì)算或系統(tǒng)級(jí)操作時(shí)，過(guò)多的 JNI 調(diào)用可能導(dǎo)致性能下降。

6.4 編寫本地方法測(cè)試

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

    static {
       //加載動(dòng)態(tài)鏈接
        System.load(System.getProperty("user.dir") +"/libnative.dylib");
    }
}

下面是如何能進(jìn)行本地方法調(diào)用的過(guò)程：

javac Hello.java -h . 將Java文件編譯為.class并產(chǎn)生頭文件。
產(chǎn)生的頭文件的展示

/* 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產(chǎn)生的方法名稱是有規(guī)則的 Java開頭 test表示包 Hello表示類 helloFromCpp表示方法
JNIEXPORT jint JNICALL Java_test_Hello_helloFromCpp
  (JNIEnv *, jobject, jint);

#ifdef __cplusplus
}
#endif
#endif

編寫頭文件對(duì)應(yīng)的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;
  }

產(chǎn)生動(dòng)態(tài)鏈接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
執(zhí)行代碼測(cè)試

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("耗時(shí)時(shí)間" + (System.currentTimeMillis() - l));
}

注意：蘋果電腦要是arm架構(gòu)的，一定要注意執(zhí)行Java程序的JDK版本要是arm架構(gòu)的。

發(fā)現(xiàn)耗時(shí)很少，所以并不是因?yàn)镴ava通過(guò)JNI執(zhí)行C語(yǔ)言代碼的問(wèn)題。

所以最終結(jié)論應(yīng)該是底層執(zhí)行C++代碼慢的緣故。