一、消失的异常堆栈

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

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

Caused by: java.lang.NullPointerException

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

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

二、Fast Throw

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

可以看出,如果某个异常在同一位置被抛出多次,会被 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 优化功能。

三、问题原因定位

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

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

然后搜索日志发现大量的 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,问题根源还是代码兼容性不足够好。

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

 

四、问题原因分析

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

很大原因是网络抖动

一般是由于链路的服务器或端口无法访问,对于虚拟机或者 docker,还需要考虑宿主机的问题。

通过系统级分析,最后确定是由于宿主机连接性问题导致 docker 实例 TCP 重传增高,当然最重要的是补充相关的指标监控。

总之,无论是在大促期间还在平时,遇到问题首先解决好问题,更为重要的是追本溯原,找出问题的根因,以便推动团队优化和提升。

作者:京东零售 张帅

来源:京东云开发者社区


↙↙↙阅读原文可查看相关链接,并与作者交流