接口從4秒到200毫秒-小小的日志竟能引發(fā)如此問題
1 問題背景
我們的業(yè)務需對接不同渠道以完成線上回收業(yè)務，然而各渠道皆有其獨特的質(zhì)檢標準。為此，我們需對質(zhì)檢標準予以統(tǒng)一化處理，將外部標準轉化為內(nèi)部可識別的質(zhì)檢標準。在此場景下，我們提供了標準映射功能，將外部質(zhì)檢項與內(nèi)部質(zhì)檢項進行關聯(lián)。此次問題源于映射關系極為復雜，在導入映射關系后，發(fā)現(xiàn)映射邏輯耗時嚴重，最終定位至日志打印問題。接下來，讓我們一同探究如何定位到日志問題以及為何輸出大量日志會致使接口變慢。
2 問題驗證
在測試環(huán)境中維護某渠道質(zhì)檢項與內(nèi)部質(zhì)檢項映射關系15000+；
發(fā)現(xiàn)模版質(zhì)檢轉換接口耗時4s左右；
圖片
將質(zhì)檢項的映射關系減少到100+時；
模版質(zhì)檢轉換接口耗時到了100毫秒左右。
圖片
圖片
發(fā)現(xiàn)模版映射接口時長確實與映射項多少有很強的關聯(lián)性。
3 問題初步定位
通過阿里的Arthas工具的trace命令可以分析方法的耗時。
圖片
經(jīng)觀察，該方法的耗時主要集中于打印日志。查看代碼得知，在將外部質(zhì)檢項映射為內(nèi)部質(zhì)檢項的過程中會產(chǎn)生大量日志，且映射關系越多，日志數(shù)量越多。因項目急于上線，故先對打印日志的代碼進行注釋，隨后發(fā)現(xiàn)接口的響應速度明顯變快。
4 初步思考
4.1 有沒有可能日志打印配置的是同步打印？
首先考慮是否為同步打印日志，畢竟同步讀寫文件會涉及磁盤隨機讀寫，進而影響效率。經(jīng)查看 log4j 的配置，得知打印日志的配置為異步打印，而非同步打印。
4.2 既然是異步打印，有沒有可能是多線程爭搶資源導致打印日志過慢呢？
排除同步打印日志的原因后，由于起初并不了解異步日志打印的底層實現(xiàn)。但依據(jù)經(jīng)驗，因需異步打印日志，需有地方存儲需要打印的日志，故而可能涉及資源爭搶。基于此想法，創(chuàng)建一個測試方法，進行單線程循環(huán)打印日志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));
}發(fā)現(xiàn)打印日志耗時為 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));
}發(fā)現(xiàn)只需要2，30毫秒。
在單線程的環(huán)境中，若打印大量日志，速度也極為緩慢，由此可見，并非是多線程的問題所致。
我們都清楚，線程池在提交任務時，若隊列已滿且達到最大線程數(shù)，便會執(zhí)行拋棄策略，其中有一種是將任務交回給提交任務的線程執(zhí)行。那么在異步日志打印過程中，倘若需打印的日志過多，使得存儲需要異步打印日志的地方滿了，是否也存在相應的拋棄策略呢？比如將異步打印轉為同步打印。所以，我決定先去探究異步打印日志的原理。
5 異步日志打印原理
5.1 Disruptor原理
經(jīng)過查詢資料發(fā)現(xiàn)，異步日志打印的底層采用的是Disruptor框架。
圖片
其基本原理為生產(chǎn)者向環(huán)形數(shù)組中存入數(shù)據(jù)，消費者則消費環(huán)形數(shù)組中的數(shù)據(jù)。sequence 用于限制生產(chǎn)者的生產(chǎn)以及消費者的消費。通過閱讀代碼得知，本質(zhì)上生產(chǎn)者會保存所有消費者以及自身的 sequence 以限制生產(chǎn)，消費者保存生產(chǎn)者來限制消費。
//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>[])
//創(chuàng)建事件處理（消費對象）
EventHandlerGroup<T> createEventProcessors(
final Sequence[] barrierSequences,
final EventHandler<? super T>[] eventHandlers) {
//....
//所有消費者的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)建事件處理（消費者）
final BatchEventProcessor<T> batchEventProcessor =
new BatchEventProcessor<>(ringBuffer, barrier, eventHandler);
//....
//將消費者的Sequence放入gatingSequences中
processorSequences[i] = batchEventProcessor.getSequence();
}
//更新生產(chǎn)者的processorSequences
updateGatingSequencesForNextInChain(barrierSequences, processorSequences);
//....
}5.2 異步日志放入Disruptor環(huán)形數(shù)組的過程
圖片
代碼
- 將數(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對象發(fā)布到環(huán)形數(shù)組中
if (!delegate.tryEnqueue(event, this)) {
//如果沒有放進去，說明隊列滿了，執(zhí)行隊列滿的處理方法，本質(zhì)上類似于線程池隊列滿丟棄策略
//ENQUEUE:將日志放入環(huán)形數(shù)組（放入不進去就循環(huán)等待，一直到放進去）
//SYNCHRONOUS:當前線程打印日志
//DISCARD:直接丟棄，忽略日志
handleQueueFull(event);
}
}
}- 放入環(huán)形數(shù)組的過程
//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)者下一個要存放到環(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)者下一個位置，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;
//判斷是否有可用容量
//實現(xiàn)原理大概就是比較Sequence（消費者消費到哪里了）和current中的較小值，與next差值是否大于環(huán)形數(shù)組的大小
if (!hasAvailableCapacity(gatingSequences, n, current)) {
throw InsufficientCapacityException.INSTANCE;
}
}
while (!cursor.compareAndSet(current, next));
return next;
}發(fā)現(xiàn)確實有類似于線程池的拋棄策略。
5.3 復用4.2中打印日志的測試代碼進行打斷點
經(jīng)過調(diào)試發(fā)現(xiàn)，在日志打印的過程中消費者消費快，沒有出現(xiàn)handleQueueFull的調(diào)用。
所以并不會經(jīng)過ENQUEUE、SYNCHRONOUS、DISCARD的三種策略的處理。
那么現(xiàn)在問題就變得十分離譜，并非上述原因所致。因此，決定采用暴力破解之法，即逐行注釋代碼的方式，以查看究竟是哪一行代碼引發(fā)了日志打印緩慢的問題。
6 將日志打印過程中的代碼進行逐行注釋，找到那一行導致日志輸出慢
6.1 定位原因發(fā)現(xiàn)是getLocation方法
經(jīng)過逐行注釋后，確定是由于getLocation方法所致。那么這行代碼究竟有何作用呢？
查詢資料得知getLocation 是用來獲取內(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
//獲取日志是哪個類，哪個方法，哪一行打印的
//舉例[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ù)向下追蹤會到下方代碼：
//org.apache.logging.log4j.util.StackLocator#calcLocation
public StackTraceElement calcLocation(final String fqcnOfLogger) {
//....
//fqcnOfLogger=org.apache.logging.slf4j.Log4jLogger
//獲取當前方法調(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;
}
//這樣就得到了誰調(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)用鏈路的長度
int depth = getStackTraceDepth();
stackTrace = new StackTraceElement[depth];
for (int i=0; i < depth; i++)
//獲取每一級調(diào)用鏈路
stackTrace[i] = getStackTraceElement(i);
} else if (stackTrace == null) {
return UNASSIGNED_STACK;
}
return stackTrace;
}
//方法都是本地方法
native int getStackTraceDepth();
native StackTraceElement getStackTraceElement(int index);通過上述跟蹤源碼，懷疑是Java調(diào)用C++代碼或者需要遍歷StackTraceElement數(shù)組導致異步日志打印過慢。
所以先將getOurStackTrace方法進行修改，不調(diào)用C++方法，直接創(chuàng)建對象，來排除不是因為遍歷數(shù)組導致的原因。
//org.apache.logging.log4j.util.StackLocator#calcLocation
public StackTraceElement calcLocation(final String fqcnOfLogger) {
//....
//fqcnOfLogger=org.apache.logging.slf4j.Log4jLogger
//將這里改為自己的寫的方法調(diào)用，構建方法調(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;
}
//這樣就得到了誰調(diào)用的日志輸出了
if (found && !fqcnOfLogger.equals(className)) {
return stackTrace[i];
}
}
return null;
}
/**
* 構建stackTraceElement數(shù)組
* @param fqcnOfLogger
* @return
*/
private StackTraceElement[] stackTraceElements(String fqcnOfLogger) {
//構建一個42長度的，保持測試代碼獲取相同長度的方法調(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í)行代碼測試代碼
@Test
private void test4(){
long l = System.currentTimeMillis();
for (int i = 0; i < 20000; i++) {
log.info(i+"");
}
System.out.println("打印日志耗時：" + (System.currentTimeMillis() - l));
}發(fā)現(xiàn)耗時只需要50毫秒，所以由此懷疑是Java調(diào)用C++代碼導致異步日志打印過慢。Java調(diào)用C++代碼用的框架叫JNI。
6.2 官方資料
圖片
這段文字說明使用堆棧跟蹤比不實用堆棧跟蹤慢30-100倍。
圖片
這張圖用來說明單線程異步日志記錄時需要記錄調(diào)用位置信息與不需要記錄調(diào)用位置信息的對比。
6.3 JNI原理
JNI調(diào)用Java代碼是一種類似反射的原理，先找到jclass、再找到jmethodId，然后調(diào)用，這樣一步步地來；
Java調(diào)用C/C++代碼創(chuàng)建對象是需要保存對象指針，然后各種操作是要將指針傳入到jni層，然后強轉到具體對象再進行操作的。
6.3.1 JNI 架構
JNI 的基本架構可以分為以下幾個部分：
- Java 代碼：調(diào)用 native 方法的 Java 類。
- JNI 頭文件：由 Java 編譯器生成的 C/C++ 頭文件，定義了 Java 類中的 native 方法。
- 本地實現(xiàn)：C/C++ 代碼實現(xiàn) native 方法的具體邏輯。
- Java 虛擬機：提供 JNI 支持的運行環(huán)境，負責加載和執(zhí)行 Java 字節(jié)碼。
6.3.2 數(shù)據(jù)類型轉換
JNI 負責在 Java 數(shù)據(jù)類型和 C/C++ 數(shù)據(jù)類型之間進行轉換。常見的數(shù)據(jù)轉換方法包括：
- Java 字符串：使用 GetStringUTFChars 和 NewStringUTF 方法進行轉換。
- Java 數(shù)組：使用 GetIntArrayElements、SetIntArrayRegion 等方法處理數(shù)組。
- Java 對象：使用 GetObjectField、CallObjectMethod 等方法訪問對象的字段和方法。
6.3.3 異常處理
JNI 提供異常處理機制，允許本地代碼檢測和拋出 Java 異常。通過 env->ExceptionCheck() 和 env->Throw 方法，可以在本地代碼中檢查異常狀態(tài)并拋出異常。
6.3.4 線程管理
JNI 允許多線程訪問 JVM，提供了與線程相關的 API，如 AttachCurrentThread 和 DetachCurrentThread，用于在本地代碼中管理 Java 線程。
6.3.5 性能考慮
- 開銷：JNI 方法調(diào)用相對 Java 方法調(diào)用來說有更高的開銷，因為涉及到上下文切換和數(shù)據(jù)轉換。
- 效率：盡管 JNI 可以提供更高的性能，特別是在需要大量計算或系統(tǒng)級操作時，過多的 JNI 調(diào)用可能導致性能下降。
6.4 編寫本地方法測試
public class Hello {
public native int helloFromCpp(int i);
static {
//加載動態(tài)鏈接
System.load(System.getProperty("user.dir") +"/libnative.dylib");
}
}下面是如何能進行本地方法調(diào)用的過程：
- 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- 編寫頭文件對應的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)生動態(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í)行代碼測試
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架構的，一定要注意執(zhí)行Java程序的JDK版本要是arm架構的。
發(fā)現(xiàn)耗時很少，所以并不是因為Java通過JNI執(zhí)行C語言代碼的問題。
所以最終結論應該是底層執(zhí)行C++代碼慢的緣故。
7 結論
- 避免打印過多無用日志，將測試過程中需要觀察的日志輸出為為 DEBUG 級別。
- 生產(chǎn)環(huán)境打印日志的級別設置為INFO。
- 如果不需要關注日志打印的位置信息，可以將日志輸出格式中的%C、%F、%l、%L、%M去掉。
8 擴展（想了解C底層實現(xiàn)）
可以查看一下下面三個類：
- jdk/src/share/native/java/lang/Throwable.c
- hotspot/src/share/vm/prims/jvm.cpp
- hotspot/src/share/vm/classfile/javaClasses.cpp
