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

京东云开发者

于 2025-05-06 17:11:11 发布

阅读量546

点赞数 23

文章标签： java 数据库开发语言

本文链接：https://blog.csdn.net/jdcdev_/article/details/147743392

版权

作者：京东物流郭忠强

导语

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

现状分析

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

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

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

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

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

•其他辅助信息：例如用户扫描或输入的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 $KaTeX parse error: Expected 'EOF', got '#' at position 7: Worker#̲run ==> ThreadP\dots$ eone$auxiliary $KaTeX parse error: Expected 'EOF', got '#' at position 8: 9f9kd21#̲call ==> Provid\dots$ original $in v o k e$ p882ot3 $a ccessor$ eone $KaTeX parse error: Expected 'EOF', got '#' at position 34: \dotserContextFilter#̲eone$ original $in v o k e$ 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 $KaTeX parse error: Expected 'EOF', got '#' at position 36: \dotsitorTemplateUmp#̲execute ==> Per\dots$ execute $KaTeX parse error: Expected 'EOF', got '#' at position 40: \dotsTemplatePayload#̲execute ==> Jsf\dots$ invoke $KaTeX parse error: Expected 'EOF', got '#' at position 28: \dotsformanceMonitor#̲doInvoke ==> Pr\dots$ DynamicAdvisedInterceptor#intercept ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor344#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1642#invoke ==> MagicAspect#magic ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 26: \dotsisedInterceptor#̲intercept ==> C\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 26: \dotsisedInterceptor#̲intercept ==> C\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1295#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 26: \dotsisedInterceptor#̲intercept ==> C\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 26: \dotsisedInterceptor#̲intercept ==> C\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AnnotationAwareRetryOperationsInterceptor#invoke ==> RetryOperationsInterceptor#invoke ==> RetryTemplate#execute ==> RetryTemplate#doExecute ==> RetryOperationsInterceptor $KaTeX parse error: Expected 'EOF', got '#' at position 2: 1#̲doWithRetry ==>\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲invokeJoinpoint\dots$ DynamicAdvisedInterceptor#intercept ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1276#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxy $KaTeX parse error: Expected 'EOF', got '#' at position 22: \dotsethodInvocation#̲proceed ==> Ref\dots$ CglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxy$CglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> StackTraceUtils#trace

2、指定包路径过滤中间件后的调用栈栈信息

LockAspect#lock ==> StockTransferAppServiceImpl#increaseStock ==> MonitorAspect#monitor ==> StockRetryExecutor#operateStock ==> StockRetryExecutor$FastClassBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 8: 5188d6e#̲invoke ==> Base\dots$ FastClassBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 9: 9d76cd9a#̲invoke ==> Stoc\dots$ FastClassBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 9: 85bb181e#̲invoke ==> Vali\dots$ EnhancerBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 9: 1388ef12#̲operateStock ==\dots$ EnhancerBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 9: 1095eafa#̲increaseStock =\dots$ FastClassBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 9: a1b4dae4#̲invoke ==> Stoc\dots$ EnhancerBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 8: b42789a#̲operateStock ==\dots$ EnhancerBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 9: 85faf510#̲go ==> StockTra\dots$ EnhancerBySpringCGLIB $KaTeX parse error: Expected 'EOF', got '#' at position 9: afc21975#̲increaseStock =\dots$ 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、同时新引入本文的工具依赖

<!-- http://sd.jd.com/article/45616?shareId=105168&isHideShareButton=1 -->
<dependency>
    <groupId>com.jd.sword</groupId>
    <artifactId>sword-utils-common</artifactId>
    <version>1.0.0-SNAPSHOT</version>
</dependency>

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

<!-- http://sd.jd.com/article/42942?shareId=105168&isHideShareButton=1 -->
<!-- SQLMarking Plugin，放在第一个Plugin的位置，不影响其他组件，但不强要求位置，也可以灵活调整顺序位置 -->
<plugin interceptor="com.jd.sword.mybatis.plugin.sql.SQLMarkingInterceptor">
    <!-- 是否开启SQL染色标记插件 -->
    <property name="enabled" value="true"/>
    <!-- 是否开启方法调用栈跟踪 -->
    <property name="stackTraceEnabled" value="true"/>
    <!-- 指定需要方法调用栈跟踪的package，减少信息量，value配置为自己工程的package路径，多个路径用英文逗号分割 -->
    <property name="specifiedStackTracePackages" value="com.jdwl.wms.stock"/>
    <!-- 结合CPU利用率和性能考虑，方法调用栈跟踪采集率配置采集率，配置示例: m/n，表示n个里面抽m个进行采集跟踪 -->
    <!-- 预发环境和测试环境可以配置全采集，例如配置1/1，生产环境可以结合CPU利用率和性能考虑按需配置采集率 -->
    <property name="stackTraceSamplingRate" value="1/2"/>
</plugin>

接入效果

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、新引入本文的工具依赖

<dependency>
    <groupId>com.jd.sword</groupId>
    <artifactId>sword-utils-common</artifactId>
    <version>1.0.0-SNAPSHOT</version>
</dependency>

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