作者：京東物流 郭忠強

導語

本文從日常值班問題排查痛點出發(fā)，分析方法復用的調(diào)用鏈路和上下文業(yè)務(wù)邏輯，通過思考分析，借助棧幀開發(fā)了一個方法調(diào)用棧的鏈式跟蹤工具，便于展示一次請求的方法串行調(diào)用鏈，有助于快速定位代碼來源和流量入口，有效提升研發(fā)和運維排查定位效率。期望在大家面臨類似痛點時可以提供一些實踐經(jīng)驗和參考，也歡迎大家合適的場景下接入使用。

?

現(xiàn)狀分析

在系統(tǒng)值班時，經(jīng)常會有人拿著報錯截圖前來咨詢，作為值班研發(fā)，我們則需要獲取盡可能多的信息，幫助我們分析報錯場景，便于排查識別問題。

例如，下圖就是一個常見的的報錯信息截圖示例。

從圖中，我們可以初步獲取到一些信息：

?菜單名稱：變更單下架，我們這是變更單下架操作時的一個報錯提醒。

?報錯信息：序列號狀態(tài)為離庫狀態(tài)，請檢查。

?其他輔助信息：例如用戶掃描或輸入的86開頭編碼，SKU、商品名稱、儲位等。

?

這時會有一些常見的排查思路：

1、根據(jù)提示，將用戶輸入的86編碼，按照提示文案去檢查用戶數(shù)據(jù)，即作為序列號編碼，去看一下序列號是否存在，是否真的是離庫了。

2、如果86編碼確實是序列號，而且真的是離庫了，那么基本上可以快速結(jié)案了，這個86編碼確實是序列號并且是已離庫，正如提示文案所示，這時跟提問人做好解釋答疑即可。

3、如果第2步排查完，發(fā)現(xiàn)86編碼不是序列號編碼，或并非離庫狀態(tài)，即與提示文案不符，這時就要定位報錯文案的代碼來源，繼續(xù)查看代碼邏輯來進行判案了。（這種也比較常見，一種是報錯場景較多，但提示文案比較單一，不便于在提示文案中覆蓋所有報錯場景；另一種提示文案陳舊未跟隨需求演變而更新。這兩點可以通過細分場景細化對應(yīng)的報錯文案，或更新報錯文案，使得報錯文案更優(yōu)更新，但不是本文討論的重點。）

4、如何根據(jù)報錯文案快速找到代碼來源呢？一般我們會在代碼庫中搜索提示文案，或者在日志中檢索報錯信息，輔助定位代碼來源，后者依賴于代碼中打印了該報錯信息，且日志級別配置能夠確保該信息打印到日志文件中。

5、倘若我們根據(jù)提示文案搜索代碼時，發(fā)現(xiàn)該提示文案有多處代碼出現(xiàn)，此時就較為復雜了，我們需要進一步識別，哪個才與本次報錯直接有關(guān)。

?

每個方法向上追溯，又發(fā)現(xiàn)調(diào)用來源眾多：

?

?

在業(yè)務(wù)復雜的系統(tǒng)中，方法復用比較常見，不同的上下文和參數(shù)傳遞，也有著不同的業(yè)務(wù)邏輯判斷和走向。

這時，基本上進入到本文要討論的痛點：如何根據(jù)有限的提示信息快速定位代碼來源？以便于分析報錯業(yè)務(wù)場景，答疑解惑或快速處理問題。

屏幕前的小伙伴，如果你也經(jīng)常值班排查問題，應(yīng)該也會有類似的痛點所在。

啟發(fā)

這是我想到了Exception異常機制，作為一名Coder，我們對異常堆棧再熟悉不過了，異常堆棧是一個“可愛”又“可恨”的東西，“可愛”在于異常堆棧確實可以幫助我們快速定位問題所在，“可恨”在于有異常基本上就是有問題，堆棧讓我們審美疲勞，累覺不愛。

下面是一個Java語言的異常堆棧信息示例：

?

異常類體系和異常處理機制在本文中不是重點，不做過多贅述，本文重點希望能從異常堆棧中獲取一些啟發(fā)。

讓我們近距離再觀察一下我們的老朋友。

在異常堆棧信息中，主要有四類信息：

?全限定類名

?方法名

?文件名

?代碼行號

這四類信息可以幫助我們有效定位代碼來源，而且堆棧中記錄行先后順序，也表示著異常發(fā)生的第一現(xiàn)場、第二現(xiàn)場、第三現(xiàn)場、……，以此傳遞。

這讓我想起了JVM方法棧中的棧幀。

每當一個方法被調(diào)用時，JVM會為該方法創(chuàng)建一個新的棧幀，并將其壓入當前線程的棧（也稱為調(diào)用棧或執(zhí)行棧)中。棧幀包含了方法執(zhí)行所需的所有信息，包括局部變量、操作數(shù)棧、常量池引用等。

?

思路

從Java中的Throwable中，可以看到staceTrace的get和set，這個StackTraceElement數(shù)組里面存放的信息就是我們在異常堆棧中經(jīng)常看到的信息。

?

?

?

再次放一下這張圖，方便對照著看。

?

StackTraceElement類的注釋中赫然寫著：

StackTraceElement represents a stack frame.

對，StackTraceElement代表著一個棧幀。

這個StackTraceElement就是我要找的東西，即使非異常情況下，每個線程在執(zhí)行方法調(diào)用時都會記錄棧幀信息。

?

按照方法調(diào)用先后順序，將調(diào)用棧中方法依次串聯(lián)起來，就像糖葫蘆一樣，就可以得到我想要的方法調(diào)用鏈了。

NEXT，我可以動工寫個工具了。

工具開發(fā)

工具的核心代碼并不復雜，StackTraceElement 也是 Java JDK 中現(xiàn)成的，我所做的工作主要是從中過濾出必要的信息，加工簡化成，按照順序整理成鏈式信息，方便我們一眼就可以看出來方法的調(diào)用鏈。

?

入?yún)⒔榻B

pretty：表示是只拼接類和方法，不拼接文件名和行號，非 pretty 是四個都會拼接。

simple：表示會過濾一些我們代碼中場景的代理增強出來的方法的信息輸出。

specifiedPrefix：指定保留相應(yīng)的包路徑堆棧信息，去掉一些過多的中間件信息。

其他還會過濾一些常見代理的堆棧信息：

?FastClassBySpringCGLIB

?EnhancerBySpringCGLIB

?lambda$

?Aspect

?Interceptor

對此，還封裝了一些默認參數(shù)的方法，使用起來更為方便。

?

還有一些其他工具方法也可以使用：

?

使用效果

1、不過濾中間件、代理增強方法的調(diào)用棧信息

Thread#run ==> ThreadPoolExecutor$Worker#run ==> ThreadPoolExecutor#runWorker ==> BaseTask#run ==> JSFTask#doRun ==> ProviderProxyInvoker#invoke ==> FilterChain#invoke ==> SystemTimeCheckFilter#invoke ==> ProviderExceptionFilter#invoke ==> ProviderContextFilter#invoke ==> InstMethodsInter#intercept ==> ProviderContextFilter$eone$auxiliary$9f9kd21#call ==> ProviderContextFilter#eone$original$invoke$p882ot3$accessor$eone$pclcbe2 ==> ProviderContextFilter#eone$original$invoke$p882ot3 ==> ProviderGenericFilter#invoke ==> ProviderUnitValidationFilter#invoke ==> ProviderHttpGWFilter#invoke ==> ProviderInvokeLimitFilter#invoke ==> ProviderMethodCheckFilter#invoke ==> ProviderTimeoutFilter#invoke ==> ValidationFilter#invoke ==> ProviderConcurrentsFilter#invoke ==> ProviderSecurityFilter#invoke ==> WmsRpcExceptionFilter#invoke ==> WmsRpcExceptionFilter#invoke4provider ==> AdmissionControlJsfFilter#invoke ==> AdmissionControlJsfFilter#providerSide ==> AdmissionControlJsfFilter#processRequest ==> ChainedDeadlineJsfFilter#invoke ==> ChainedDeadlineJsfFilter#providerSide ==> JsfPerformanceMonitor#invoke ==> AbstractMiddlewarePerformanceMonitor#doExecute ==> PerformanceMonitorTemplateComposite#execute ==> PerformanceMonitorTemplateComposite#lambda$execute$0 ==> PerformanceMonitorTemplateUmp#execute ==> PerformanceMonitorTemplateComposite#lambda$execute$0 ==> PerformanceMonitorTemplatePayload#execute ==> JsfPerformanceMonitor#lambda$invoke$0 ==> JsfPerformanceMonitor#doInvoke ==> ProviderInvokeFilter#invoke ==> ProviderInvokeFilter#reflectInvoke ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1704#invoke ==> CglibAopProxy$DynamicAdvisedInterceptor#intercept ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor344#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1276#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1642#invoke ==> MagicAspect#magic ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy$CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy$DynamicAdvisedInterceptor#intercept ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy$CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy$DynamicAdvisedInterceptor#intercept ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1295#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy$CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy$DynamicAdvisedInterceptor#intercept ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy$CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy$DynamicAdvisedInterceptor#intercept ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AnnotationAwareRetryOperationsInterceptor#invoke ==> RetryOperationsInterceptor#invoke ==> RetryTemplate#execute ==> RetryTemplate#doExecute ==> RetryOperationsInterceptor$1#doWithRetry ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy$CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy$DynamicAdvisedInterceptor#intercept ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1276#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> TransactionInterceptor#invoke ==> TransactionAspectSupport#invokeWithinTransaction ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> PersistenceExceptionTranslationInterceptor#invoke ==> CglibAopProxy$CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy$CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> StackTraceUtils#trace

2、指定包路徑過濾中間件后的調(diào)用棧棧信息

LockAspect#lock ==> StockTransferAppServiceImpl#increaseStock ==> MonitorAspect#monitor ==> StockRetryExecutor#operateStock ==> StockRetryExecutor$$FastClassBySpringCGLIB$$5188d6e#invoke ==> BaseStockOperation$$FastClassBySpringCGLIB$$9d76cd9a#invoke ==> StockTransferServiceImpl$$FastClassBySpringCGLIB$$85bb181e#invoke ==> ValidationAspect#logAndReturn ==> LogAspect#log ==> ThreadLocalRemovalAspect#removal ==> ValidationAspect#validate ==> BaseStockOperation#go ==> StockRepositoryImpl$$EnhancerBySpringCGLIB$$1388ef12#operateStock ==> StockTransferAppServiceImpl$$EnhancerBySpringCGLIB$$1095eafa#increaseStock ==> StockRepositoryImpl$$FastClassBySpringCGLIB$$a1b4dae4#invoke ==> StockTransferServiceImpl#increaseStock ==> DataBaseExecutor#execute ==> StockRetryExecutor$$EnhancerBySpringCGLIB$$b42789a#operateStock ==> StockInitializer$$EnhancerBySpringCGLIB$$85faf510#go ==> StockTransferServiceImpl$$EnhancerBySpringCGLIB$$afc21975#increaseStock ==> StockRepositoryImpl#operateStock ==> DataBaseExecutor#operate ==> StockTransferAppServiceImpl$$FastClassBySpringCGLIB$$e348d8e1#invoke

3、去掉Spring代理增強之后的調(diào)用棧信息

LogAspect#log ==> LockAspect#lock ==> ValidationAspect#validate ==> ValidationAspect#logAndReturn ==> MonitorAspect#monitor ==> StockTransferAppServiceImpl#decreaseStock ==> ThreadLocalRemovalAspect#removal ==> StockTransferServiceImpl#decreaseStock ==> StockOperationLoader#go ==> BaseStockOperation#go ==> DataBaseExecutor#operate ==> DataBaseExecutor#execute ==> StockRetryExecutor#operateStock ==> StockRepositoryImpl#operateStock

4、去掉一些自定義代理之后的調(diào)用棧棧信息

StockTransferAppServiceImpl#increaseStock ==> StockTransferServiceImpl#increaseStock ==> BaseStockOperation#go ==> DataBaseExecutor#operate ==> DataBaseExecutor#execute ==> StockRetryExecutor#operateStock ==> StockRepositoryImpl#operateStock

5、如果帶上文件名和行號后的調(diào)用棧棧信息

StockTransferAppServiceImpl#increaseStock(StockTransferAppServiceImpl.java:103) ==> StockTransferServiceImpl#increaseStock(StockTransferServiceImpl.java:168) ==> BaseStockOperation#go(BaseStockOperation.java:152) ==> BaseStockOperation#go(BaseStockOperation.java:181) ==> BaseStockOperation#go(BaseStockOperation.java:172) ==> DataBaseExecutor#operate(DataBaseExecutor.java:34) ==> DataBaseExecutor#operate(DataBaseExecutor.java:64) ==> DataBaseExecutor#execute(DataBaseExecutor.java:79) ==> StockRetryExecutor#operateStock(StockRetryExecutor.java:64) ==> StockRepositoryImpl#operateStock(StockRepositoryImpl.java:303)

?

線上應(yīng)用實踐

接入方法調(diào)用棧跟蹤工具后，根據(jù)報錯提示詞，可以檢索到對應(yīng)日志，從 ImmediateTransferController#offShelf ==> AopConfig#pointApiExpression ==> TransferOffShelfAppServiceImpl#offShelf ==> TransferOffShelfAppServiceImpl#doOffShelf 中順藤摸瓜可以快速找到流量入口的代碼位置。

?

?

?

適用場景

該方法調(diào)用棧工具類，可以在一些堆棧信息進行輔助排查分析的地方進行預埋，例如：

?業(yè)務(wù)異常時輸出堆棧到日志信息中。

?業(yè)務(wù)監(jiān)控告警信息中加入調(diào)用棧信息。

?一些復用方法調(diào)用復雜場景下，打印調(diào)用棧信息，展示調(diào)用鏈，方便分析。

?其他一些場景等。

延伸

在《如何一眼定位SQL的代碼來源：一款SQL染色標記的簡易MyBatis插件》一文中，我發(fā)布了一款SQL染色插件，該插件目前已有statementId信息，還支持通過SQLMarkingThreadLocal傳遞自定義附加信息。其他BGBU的技術(shù)小伙伴，也有呼聲，希望在statementId基礎(chǔ)上可以繼續(xù)追溯入口方法。通過本文引入的方法調(diào)用棧跟蹤工具，我在SQL染色插件中增加了方法調(diào)用棧染色信息。

SQL染色工具新版特性，歡迎大家先在TEST和UAT環(huán)境嘗鮮試用，TEST和UAT環(huán)境驗證沒問題后，再逐步推廣正式環(huán)境。

升級方法：

1、sword-mybatis-plugins版本升級至1.0.6-SNAPSHOT。

2、同時新引入本文的工具依賴

    com.jd.sword
    sword-utils-common
    1.0.0-SNAPSHOT

3、mybatis config xml 配置文件按最新配置調(diào)整

接入效果

SELECT
	id,
	tenant_code,
	warehouse_no,
	sku,
	location_no,
	container_level_1,
	container_level_2,
	lot_no,
	sku_level,
	owner_no,
	pack_code,
	conversion_rate,
	stock_qty,
	prepicked_qty,
	premoved_qty,
	frozen_qty,
	diff_qty,
	broken_qty,
	status,
	md5_value,
	version,
	create_user,
	update_user,
	create_time,
	update_time,
	extend_content
FROM
	st_stock
WHERE
	deleted = 0
	AND warehouse_no = ?
	AND location_no IN(?)
	AND container_level_1 IN(?)
	AND container_level_2 IN(?)
	AND sku IN(?)
	/* [SQLMarking] statementId: com.jdwl.wms.stock.infrastructure.jdbc.main.dao.StockQueryDao.selectExtendedStockByLocation, stackTrace: BaseJmqConsumer#onMessage ==> StockInfoConsumer#handle ==> StockInfoConsumer#handleEvent ==> StockExtendContentFiller#fillExtendContent ==> StockInitializer#queryStockByWarehouse ==> StockInitializer#batchQueryStockByWarehouse ==> StockInitializer#queryByLocationAndSku ==> StockQueryRepositoryImpl#queryExtendedStockByLocationAndSku, warehouseNo: 6_6_601 */

如何接入本文工具？

如果小伙伴也有類似使用訴求，大家可以先在測試、UAT環(huán)境接入試用，然后再逐步推廣線上生產(chǎn)環(huán)境。

1、新引入本文的工具依賴

    com.jd.sword
    sword-utils-common
    1.0.0-SNAPSHOT

2、使用工具類靜態(tài)方法

com.jd.sword.utils.common.runtime.StackTraceUtils#simpleTrace()

com.jd.sword.utils.common.runtime.StackTraceUtils#simpleTrace(java.lang.String...)

com.jd.sword.utils.common.runtime.StackTraceUtils#trace()

com.jd.sword.utils.common.runtime.StackTraceUtils#trace(java.lang.String...)

com.jd.sword.utils.common.runtime.StackTraceUtils#trace(boolean)

com.jd.sword.utils.common.runtime.StackTraceUtils#trace(boolean, boolean, java.lang.String...)



審核編輯 黃宇