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

2023-06-29 10:15:04 | 来源:博客园
一、消失的异常堆栈

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

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


【资料图】

Caused by: java.lang.NullPointerException

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

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

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
10w996ms3525ms
100w5983ms28345ms
500w35678ms——

言而简之,不能因此出现了消失的异常堆栈就尝试关闭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 errorcom.jd.sirector.SirectorException: java.lang.NullPointerExceptionat 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.NullPointerExceptionat com.jd.******************wProxy.java:321) ~[shop-soa-service-1.1.jar:?]**************... 5 more19:05:44.063 [JSF-BZ-22001-245-T-503] ERROR com.jd.m.soa.shop.service.jsf.shop.impl.ShopSoaOutSideJsfServiceImpl - ShopSoaOutSideJsfServiceImpl.getKACard errorcom.jd.sirector.SirectorException: java.lang.NullPointerExceptionat 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.NullPointerException19: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。快速重传则依赖于数据包的期望序列号,并进行一致性检查。

多台机器或者同一机房同时TCP重传

很大原因是网络抖动

单机或者某个应用出现TCP重传

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

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

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

作者:京东零售 张帅

来源:京东云开发者社区

上一篇 下一篇

相关新闻

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

不为高额回报所诱惑,守好养老钱

江湖夜雨十年灯的意思_诗句江湖夜雨十年灯的翻译

分析师:特斯拉第二季度中国销售将再创新高 但市场份额或萎缩|世界快资讯

雁南飞歌词及简谱(雁南飞歌词) 资讯

星宇股份:6月28日融券卖出金额99.57万元,占当日流出金额的3.05% 每日短讯

紫陀螺(紫陀螺) 全球热点

有人坐吗?高级动卧票价一站8分钟420元 跟二等座差价70倍:12306回应

捷克公开赛国乒遭遇二连败!一单项全军覆没,伊藤美诚零封何卓佳_每日快播

C视频 | 聚焦西博会 部分市州今日签约

世界实时:虹膜识别板块6月28日跌1.6%,熵基科技领跌,主力资金净流出1.18亿元

环球即时看!能上网但是浏览器打不开网页(能上网)

鸟类环志站_关于鸟类环志站简述|今日热议

中超-梅里达传射罗萨双响 津门虎3-2青岛海牛_环球观焦点

环球今热点:广州公交41辆纯电动G6公交车正式投入运营

最新新闻

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

不为高额回报所诱惑,守好养老钱

江湖夜雨十年灯的意思_诗句江湖夜雨十年灯的翻译

分析师:特斯拉第二季度中国销售将再创新高 但市场份额或萎缩|世界快资讯

雁南飞歌词及简谱(雁南飞歌词) 资讯

星宇股份:6月28日融券卖出金额99.57万元,占当日流出金额的3.05% 每日短讯

紫陀螺(紫陀螺) 全球热点

有人坐吗?高级动卧票价一站8分钟420元 跟二等座差价70倍:12306回应

捷克公开赛国乒遭遇二连败!一单项全军覆没,伊藤美诚零封何卓佳_每日快播

C视频 | 聚焦西博会 部分市州今日签约

世界实时:虹膜识别板块6月28日跌1.6%,熵基科技领跌,主力资金净流出1.18亿元

环球即时看!能上网但是浏览器打不开网页(能上网)

鸟类环志站_关于鸟类环志站简述|今日热议

中超-梅里达传射罗萨双响 津门虎3-2青岛海牛_环球观焦点

环球今热点:广州公交41辆纯电动G6公交车正式投入运营

央行上海总部:5月长三角地区人民币贷款增加4071亿元,存款增加1764亿元

全球要闻:倒计时30天!成都大运会,准备好了

94岁战地摄影记者张崇岫:“我老了,但图片里的故事不老-当前热文

主力资金|新能源个股久违大涨,主力大手笔抢筹 环球关注

世界即时看!无忧传媒将与百度百科开展深度合作 探索扩大内需新模式

今日快讯:合同能源管理合同范本由谁发布_最新合同能源管理合同范本

每日快讯!桃源茶庵铺镇:持续开展人居环境整治 让良好生态成为乡村振兴支撑点

世界今热点:【双语视听】Zhengzhou, here we come! “国际消费郑”来了!

2023年青岛五险一金缴费标准一览表 2023年青岛五险一金每月多少钱?

A股收评 | A股深V反弹!煤炭、电力扛大旗 减速器概念站上风口 中马传动(603767.SH)7天6板

机动车右转未礼让 撞伤电动自行车骑车人_当前要闻

探寻世界能源转型解决方案

全球消息!殖民旧痕:伪满皇宫博物院暨东北沦陷史陈列馆

TOPcon电池板块震荡反弹-每日速递

世界播报:日本警方逮捕中国籍研究员,我使馆发声