接口從4秒到200毫秒-小小的日志竟能引發如此問題

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

我們的業務需對接不同渠道以完成線上回收業務，然而各渠道皆有其獨特的質檢標準。為此，我們需對質檢標準予以統一化處理，將外部標準轉化為內部可識別的質檢標準。

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

責任編輯：武曉燕來源：轉轉技術

日志接口異步

成人免费xxxxx在线视频软件_久久精品久久久_亚洲国产精品久久久_天天色天天色_亚洲人成一区_欧美一级欧美三级在线观看