作者：京东物流 郭忠强

导语

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

现状分析

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

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

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

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

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

•其他辅助信息：例如用户扫描或输入的 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 ==> ThreadPoolExecutorWorker#run ==> ThreadPoolExecutor#runWorker ==> BaseTask#run ==> JSFTask#doRun ==> ProviderProxyInvoker#invoke ==> FilterChain#invoke ==> SystemTimeCheckFilter#invoke ==> ProviderExceptionFilter#invoke ==> ProviderContextFilter#invoke ==> InstMethodsInter#intercept ==> ProviderContextFiltereone$auxiliary$9f9kd21#call ==> ProviderContextFilter#eone$original$invoke$p882ot3$accessor$eone$pclcbe2 ==> ProviderContextFilter#eone$original$invokep882ot3 ==> 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#lambdaexecute0 ==> PerformanceMonitorTemplateUmp#execute ==> PerformanceMonitorTemplateComposite#lambdaexecute0 ==> PerformanceMonitorTemplatePayload#execute ==> JsfPerformanceMonitor#lambdainvoke0 ==> JsfPerformanceMonitor#doInvoke ==> ProviderInvokeFilter#invoke ==> ProviderInvokeFilter#reflectInvoke ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1704#invoke ==> CglibAopProxyDynamicAdvisedInterceptor#intercept ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor344#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1276#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1642#invoke ==> MagicAspect#magic ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxyCglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxyDynamicAdvisedInterceptor#intercept ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxyCglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxyDynamicAdvisedInterceptor#intercept ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1295#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor868#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxyCglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxyDynamicAdvisedInterceptor#intercept ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxyCglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxyDynamicAdvisedInterceptor#intercept ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AnnotationAwareRetryOperationsInterceptor#invoke ==> RetryOperationsInterceptor#invoke ==> RetryTemplate#execute ==> RetryTemplate#doExecute ==> RetryOperationsInterceptor1#doWithRetry ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> CglibAopProxyCglibMethodInvocation#invokeJoinpoint ==> MethodProxy#invoke ==> CglibAopProxyDynamicAdvisedInterceptor#intercept ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> ExposeInvocationInterceptor#invoke ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor1276#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> TransactionInterceptor#invoke ==> TransactionAspectSupport#invokeWithinTransaction ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> AspectJAroundAdvice#invoke ==> AbstractAspectJAdvice#invokeAdviceMethod ==> AbstractAspectJAdvice#invokeAdviceMethodWithGivenArgs ==> Method#invoke ==> DelegatingMethodAccessorImpl#invoke ==> GeneratedMethodAccessor869#invoke ==> MethodInvocationProceedingJoinPoint#proceed ==> CglibAopProxyCglibMethodInvocation#proceed ==> ReflectiveMethodInvocation#proceed ==> PersistenceExceptionTranslationInterceptor#invoke ==> CglibAopProxyCglibMethodInvocation#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、同时新引入本文的工具依赖

<!-- 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_contentFROM  st_stockWHERE  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...)