研发排查问题的利器：一款方法调用栈跟踪工具-电子发烧友网

作者：京东物流郭忠强

导语

本文从日常值班问题排查痛点出发，分析方法复用的调用链路和上下文业务逻辑，通过思考分析，借助栈帧开发了一个方法调用栈的链式跟踪工具，便于展示一次请求的方法串行调用链，有助于快速定位代码来源和流量入口，有效提升研发和运维排查定位效率。期望在大家面临类似痛点时可以提供一些实践经验和参考，也欢迎大家合适的场景下接入使用。

现状分析

在系统值班时，经常会有人拿着报错截图前来咨询，作为值班研发，我们则需要获取尽可能多的信息，帮助我们分析报错场景，便于排查识别问题。

例如，下图就是一个常见的的报错信息截图示例。

从图中，我们可以初步获取到一些信息：

?菜单名称：变更单下架，我们这是变更单下架操作时的一个报错提醒。

?报错信息：序列号状态为离库状态，请检查。

?其他辅助信息：例如用户扫描或输入的86开头编码，SKU、商品名称、储位等。

这时会有一些常见的排查思路：

1、根据提示，将用户输入的86编码，按照提示文案去检查用户数据，即作为序列号编码，去看一下序列号是否存在，是否真的是离库了。

2、如果86编码确实是序列号，而且真的是离库了，那么基本上可以快速结案了，这个86编码确实是序列号并且是已离库，正如提示文案所示，这时跟提问人做好解释答疑即可。

3、如果第2步排查完，发现86编码不是序列号编码，或并非离库状态，即与提示文案不符，这时就要定位报错文案的代码来源，继续查看代码逻辑来进行判案了。（这种也比较常见，一种是报错场景较多，但提示文案比较单一，不便于在提示文案中覆盖所有报错场景；另一种提示文案陈旧未跟随需求演变而更新。这两点可以通过细分场景细化对应的报错文案，或更新报错文案，使得报错文案更优更新，但不是本文讨论的重点。）

4、如何根据报错文案快速找到代码来源呢？一般我们会在代码库中搜索提示文案，或者在日志中检索报错信息，辅助定位代码来源，后者依赖于代码中打印了该报错信息，且日志级别配置能够确保该信息打印到日志文件中。

5、倘若我们根据提示文案搜索代码时，发现该提示文案有多处代码出现，此时就较为复杂了，我们需要进一步识别，哪个才与本次报错直接有关。

每个方法向上追溯，又发现调用来源众多：

在业务复杂的系统中，方法复用比较常见，不同的上下文和参数传递，也有着不同的业务逻辑判断和走向。

这时，基本上进入到本文要讨论的痛点：如何根据有限的提示信息快速定位代码来源？以便于分析报错业务场景，答疑解惑或快速处理问题。

屏幕前的小伙伴，如果你也经常值班排查问题，应该也会有类似的痛点所在。

启发

这是我想到了Exception异常机制，作为一名Coder，我们对异常堆栈再熟悉不过了，异常堆栈是一个“可爱”又“可恨”的东西，“可爱”在于异常堆栈确实可以帮助我们快速定位问题所在，“可恨”在于有异常基本上就是有问题，堆栈让我们审美疲劳，累觉不爱。

下面是一个Java语言的异常堆栈信息示例：

异常类体系和异常处理机制在本文中不是重点，不做过多赘述，本文重点希望能从异常堆栈中获取一些启发。

让我们近距离再观察一下我们的老朋友。

在异常堆栈信息中，主要有四类信息：

?全限定类名

?方法名

?文件名

?代码行号

这四类信息可以帮助我们有效定位代码来源，而且堆栈中记录行先后顺序，也表示着异常发生的第一现场、第二现场、第三现场、……，以此传递。

这让我想起了JVM方法栈中的栈帧。

每当一个方法被调用时，JVM会为该方法创建一个新的栈帧，并将其压入当前线程的栈（也称为调用栈或执行栈)中。栈帧包含了方法执行所需的所有信息，包括局部变量、操作数栈、常量池引用等。

思路

从Java中的Throwable中，可以看到staceTrace的get和set，这个StackTraceElement数组里面存放的信息就是我们在异常堆栈中经常看到的信息。

再次放一下这张图，方便对照着看。

StackTraceElement类的注释中赫然写着：

StackTraceElement represents a stack frame.

对，StackTraceElement代表着一个栈帧。

这个StackTraceElement就是我要找的东西，即使非异常情况下，每个线程在执行方法调用时都会记录栈帧信息。

按照方法调用先后顺序，将调用栈中方法依次串联起来，就像糖葫芦一样，就可以得到我想要的方法调用链了。

NEXT，我可以动工写个工具了。

工具开发

工具的核心代码并不复杂，StackTraceElement 也是 Java JDK 中现成的，我所做的工作主要是从中过滤出必要的信息，加工简化成，按照顺序整理成链式信息，方便我们一眼就可以看出来方法的调用链。

入参介绍

pretty：表示是只拼接类和方法，不拼接文件名和行号，非 pretty 是四个都会拼接。

simple：表示会过滤一些我们代码中场景的代理增强出来的方法的信息输出。

specifiedPrefix：指定保留相应的包路径堆栈信息，去掉一些过多的中间件信息。

其他还会过滤一些常见代理的堆栈信息：

?FastClassBySpringCGLIB

?EnhancerBySpringCGLIB

?lambda$

?Aspect

?Interceptor

对此，还封装了一些默认参数的方法，使用起来更为方便。

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

使用效果

1、不过滤中间件、代理增强方法的调用栈信息

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、指定包路径过滤中间件后的调用栈栈信息

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代理增强之后的调用栈信息

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、去掉一些自定义代理之后的调用栈栈信息

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

5、如果带上文件名和行号后的调用栈栈信息

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)

线上应用实践

接入方法调用栈跟踪工具后，根据报错提示词，可以检索到对应日志，从 ImmediateTransferController#offShelf ==> AopConfig#pointApiExpression ==> TransferOffShelfAppServiceImpl#offShelf ==> TransferOffShelfAppServiceImpl#doOffShelf 中顺藤摸瓜可以快速找到流量入口的代码位置。

适用场景

该方法调用栈工具类，可以在一些堆栈信息进行辅助排查分析的地方进行预埋，例如：

?业务异常时输出堆栈到日志信息中。

?业务监控告警信息中加入调用栈信息。

?一些复用方法调用复杂场景下，打印调用栈信息，展示调用链，方便分析。

?其他一些场景等。

延伸

在《如何一眼定位SQL的代码来源：一款SQL染色标记的简易MyBatis插件》一文中，我发布了一款SQL染色插件，该插件目前已有statementId信息，还支持通过SQLMarkingThreadLocal传递自定义附加信息。其他BGBU的技术小伙伴，也有呼声，希望在statementId基础上可以继续追溯入口方法。通过本文引入的方法调用栈跟踪工具，我在SQL染色插件中增加了方法调用栈染色信息。

SQL染色工具新版特性，欢迎大家先在TEST和UAT环境尝鲜试用，TEST和UAT环境验证没问题后，再逐步推广正式环境。

升级方法：

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

2、同时新引入本文的工具依赖



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

3、mybatis config xml 配置文件按最新配置调整

接入效果

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环境接入试用，然后再逐步推广线上生产环境。

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


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

2、使用工具类静态方法

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...)



审核编辑 黄宇

声明：本文内容及配图由入驻作者撰写或者入驻合作网站授权转载。文章观点仅代表作者本人，不代表电子发烧友网立场。文章及其配图仅供工程师学习之用，如有内容侵权或者其他违规问题，请联系本站处理。举报投诉

编程

编程

+关注

关注
88

文章
3689

浏览量
95389
SQL

SQL

+关注

关注
1

文章
783

浏览量
45365
定位

定位

+关注

关注
5

文章
1456

浏览量
36033

搜索历史

研发排查问题的利器：一款方法调用栈跟踪工具

评论