如何从消失的异常堆栈定位线上问题

京东技术

发布于 2023-09-13 15:36:11

2560

发布于 2023-09-13 15:36:11

文章被收录于专栏：京东技术

Tech 导读在系统开发和运维过程中，异常堆栈信息是解决线上问题的关键之一。然而，有时候异常堆栈信息可能会消失，带来严重的麻烦。本文将介绍消失的异常堆栈的原因，即JIT编译器对异常进行的优化，以及如何快速定位问题。此外，还将讨论异常优化机制Fast Throw的使用条件和性能影响。通过一个实际案例，将详细阐述如何通过追溯日志和分析系统指标来定位问题的根因。无论是在大促期间还是平时运维中，追本溯源并解决问题的能力都是非常关键的。阅读本文，您将对异常堆栈消失问题有更深入的了解，并掌握解决问题的方法和技巧。

01

消失的异常堆栈

在今年的敏捷团队建设中，我通过Suite执行器实现了一键自动化单元测试。Juint除了Suite执行器还有哪些执行器呢？由此我的Runner探索之旅开始了！

在618保障大促稳定性过程中，消失的异常堆栈可能会带来严重的麻烦，因为这些堆栈信息是我们解决线上问题的关键之一。如何快速定位问题？想必大家心中都有自己的答案，当然最简单直接的办法还是查找异常堆栈信息。

然而有时异常堆栈并不完整，只有一句描述，如下：

Caused by: java.lang.NullPointerException

造成这种现象的原因其实很简单，原因如下：

JIT编译器对异常进行了优化，当代码中的某个位置抛出同一个异常很多次后,
JIT服务端编译器(C2)会将其优化成抛出一个事先编译好的、类型匹配的异常,异常堆栈信息就看不到了。

02

Fast

Throw

理解，首先 MCube 会依据模板缓存状态判断是否需要网络获取最新模板，当获取到模板后进行模板加载，加载阶段会将产物转换为视图树的结构，转换完成后将通过表达式引擎解析表达式并取得正确的值，通过事件解析引擎解析用户自定义事件并完成事件的绑定，完成解析赋值以及事件绑定后进行视图的渲染，最终将目标页面展示到屏幕。

Fast Throw，字段上理解就是快速抛异常，目前需要满足以下条件才有如此的优化：

只针对HotSpot VM才有, 例如oracleJDK, libericaJDK等
特定位置抛出很多次,其实就是JIT将它优化了
JIT必须使用C2才会这样优化,不抛出原来的异常,改用fast throw抛出
这是一个事先分配好的异常,message和堆栈都是空的

可以看出,如果某个异常在同一位置被抛出多次，会被JIT C2优化成空异常,例如本文的NullPointerException，既没有message，也没有堆栈。但他的速度非常快，不用分配内存和获取堆栈。

如果想关闭这个优化，设置-XX:-OmitStackTraceInFastThrow即可。

存在即合理，既然存在fast throw的优化，必然有其价值。fast throw优化的原因是为了提高性能。当同一种异常在相同的位置被抛出多次，编译器就会重新编译此方法。重编译后，编译器可能会使用不提供跟踪的预分配异常来选择更快的策略。

本地测试了一下抛出NullPointerException，再开启与关闭fast throw的性能。

执行次数	开启Fast Throw	关闭Fast Throw
10w	996ms	3525ms
100w	5983ms	28345ms
500w	35678ms	——

言而简之，不能因出现了消失的异常堆栈就尝试关闭fast throw优化功能。

03

问题原因定位

理解，首先 MCube 会依据模板缓存状态判断是否需要网络获取最新模板，当获取到模板后进行模板加载，加载阶段会将产物转换为视图树的结构，转换完成后将通过表达式引擎解析表达式并取得正确的值，通过事件解析引擎解析用户自定义事件并完成事件的绑定，完成解析赋值以及事件绑定后进行视图的渲染，最终将目标页面展示到屏幕。

对于线上环境中触发了Fast Throw机制，则可以通过向前追溯相同的日志来定位问题。

如在开门红中，有个接口的可用率调到98.3%（不是100%），如下图。

图1.在开门红中有个接口的可用率调到98.3%

然后搜索日志发现大量的Caused by: java.lang.NullPointerException，没有详细的异常堆栈，很显然是由于fast throw导致的，然后不断向前追溯相同的日志来定位问题如下。

19:05:32.592 [JSF-BZ-22001-245-T-522] ERROR com.jd.m.soa.shop.service.jsf.shop.impl.ShopSoaOutSideJsfServiceImpl - ShopSoaOutSideJsfServiceImpl.getKACard error
com.jd.sirector.SirectorException: java.lang.NullPointerException
  at com.jd.sirector.ScriptRuntime.waitIfNecessary(ScriptRuntime.java:129) ~[sirector-core-0.2.2-beta.jar:?]
  at com.jd.sirector.ScriptRuntime.run(ScriptRuntime.java:66) ~[sirector-core-0.2.2-beta.jar:?]
  at com.jd.sirector.Sirector.publish(Sirector.java:153) ~[sirector-core-0.2.2-beta.jar:?]
  ****************
  at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_60]
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_60]
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_60]
  at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_60]
Caused by: java.lang.NullPointerException
  at com.jd.******************wProxy.java:321) ~[shop-soa-service-1.1.jar:?]
  **************
  ... 5 more
19:05:44.063 [JSF-BZ-22001-245-T-503] ERROR com.jd.m.soa.shop.service.jsf.shop.impl.ShopSoaOutSideJsfServiceImpl - ShopSoaOutSideJsfServiceImpl.getKACard error
com.jd.sirector.SirectorException: java.lang.NullPointerException
  at com.jd.sirector.ScriptRuntime.waitIfNecessary(ScriptRuntime.java:129) ~[sirector-core-0.2.2-beta.jar:?]
  at com.jd.sirector.ScriptRuntime.run(ScriptRuntime.java:66) ~[sirector-core-0.2.2-beta.jar:?]
  at com.jd.sirector.Sirector.publish(Sirector.java:153) ~[sirector-core-0.2.2-beta.jar:?]
  ****************
  at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_60]
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_60]
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_60]
  at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_60]
Caused by: java.lang.NullPointerException
19:05:47.831 [pool-84-thread-10] ERROR com.jd.m.soa.shop.service.base.shop.impl.ShopBaseServiceImpl - 上游返回的店铺星级值非法。value=0.0

出现问题的原因找到了，接着就分析原因。原因很简单，由于某一台机器性能波动导致接口超时将兜底对象缓存，后续逻辑在处理的过种中对象中的Boolean属性值在转boolean时出现NPE，问题根源还是代码兼容性不足够好。

图2.原因分析示意

对这台机器进行系统视图层分析，发现TCP重传数较高，如下图。

图3、4.系统视图层分析示意

04

问题原因分析

理解，首先 MCube 会依据模板缓存状态判断是否需要网络获取最新模板，当获取到模板后进行模板加载，加载阶段会将产物转换为视图树的结构，转换完成后将通过表达式引擎解析表达式并取得正确的值，通过事件解析引擎解析用户自定义事件并完成事件的绑定，完成解析赋值以及事件绑定后进行视图的渲染，最终将目

TCP重传主要是为了保证数据传输的可靠性，TCP是一种保证可靠传输的机制，如重传与确认机制、数据校验、数据分片、流量控制、拥塞控制等。TCP重传的类型有超时重传和快速重传。超时重传是在请求包发送出去时开启计时器，当到达时间之后，没有收到ACK，则进行重传直到达到上限次数或者收到ACK。快速重传则依赖于数据包的期望序列号，并进行一致性检查。