在618保障大促稳定性过程中,消失的异常堆栈可能会带来严重的麻烦,因为这些堆栈信息是我们解决线上问题的关键之一。如何快速定位问题?想必大家心中都有自己的答案,当然最简单直接的办法还是查找异常堆栈信息。
Caused by: java.lang.NullPointerException
JIT编译器对异常进行了优化,当代码中的某个位置抛出同一个异常很多次后,
JIT服务端编译器(C2)会将其优化成抛出一个事先编译好的、类型匹配的异常,异常堆栈信息就看不到了。
只针对HotSpot VM才有, 例如oracleJDK, libericaJDK等
特定位置抛出很多次,其实就是JIT将它优化了
JIT必须使用C2才会这样优化,不抛出原来的异常,改用fast throw抛出
执行次数 | 开启Fast Throw | 关闭Fast Throw |
---|---|---|
10w | 996ms | 3525ms |
100w | 5983ms | 28345ms |
500w | 35678ms | —— |
如在开门红中,有个接口的可用率调到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
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
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
图2.原因分析示意
对这台机器进行系统视图层分析,发现TCP重传数较高,如下图。
多台机器或者同一机房同时TCP重传
单机或者某个应用出现TCP重传
通过系统级分析,最后确定是由于宿主机连接性问题导致docker实例TCP重传增高,当然最重要的是补充相关的指标监控。
求分享
求点赞
求在看