如何从消失的异常堆栈定位线上问题 | 京东云技术团队

京东云开发者
• 阅读 341

一、消失的异常堆栈

在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
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。快速重传则依赖于数据包的期望序列号,并进行一致性检查。

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

很大原因是网络抖动

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

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

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

如何从消失的异常堆栈定位线上问题 | 京东云技术团队

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

作者:京东零售 张帅

来源:京东云开发者社区

点赞
收藏
评论区
推荐文章
Stella981 Stella981
3年前
JVM调优之jstack找出最耗cpu的线程并定位代码
jstack可以定位到线程堆栈,根据堆栈信息我们可以定位到具体代码,所以它在JVM性能调优中使用得非常多。下面我们来一个实例找出某个Java进程中最耗费CPU的Java线程并定位堆栈信息,用到的命令有ps、top、printf、jstack、grep。第一步先找出Java进程ID,服务器上的Java应用名称为mrfcenter:root@u
Wesley13 Wesley13
3年前
Java运行状态分析2:获取线程状态及堆栈信息
Java运行状态分析2:线程状态及堆栈信息基本概念出现内存泄漏或者运行缓慢场景,有时候无法直接从业务日志看出问题时候,需要分析jvm内存和线程堆栈线程堆栈信息主要记录jvm线程在某时刻线程执行情况,分析线程状态可以跟踪到程序出问题的地方​内存堆栈信息主要记录jvm堆中在某时刻对象使用情况,
Wesley13 Wesley13
3年前
Java获取异常堆栈信息
Java获取异常堆栈信息(https://www.oschina.net/action/GoToLink?urlhttp%3A%2F%2Fwww.cnblogs.com%2Fzhileaf%2Fp%2F6288769.html)
Stella981 Stella981
3年前
Executors使用不当引起的内存泄漏
线上服务内存溢出这周刚上班突然有一个项目内存溢出了,排查了半天终于找到问题所在,在此记录下,防止后面再次出现类似的情况。先简单说下当出现内存溢出之后,我是如何排查的,首先通过jstack打印出堆栈信息,然后通过分析工具对这些文件进行分析,根据分析结果我们就可以知道大概是由于什么问题引起的。关于jstack如何使用,大家可以先看看这篇文章
Stella981 Stella981
3年前
Linux下coredump使用
01什么coredump当程序运行的过程中异常终止或崩溃,操作系统会将程序当时的内存状态记录下来,保存在一个文件中(core文件),这种行为就叫做CoreDump或者叫做"核心转储",利用coredump可以帮助我们快速定位程序崩溃位置。通常情况下,core文件会包含了程序运行时的内存,寄存器状态,堆栈指针,
Wesley13 Wesley13
3年前
MySQL部分从库上面因为大量的临时表tmp_table造成慢查询
背景描述Time:20190124T00:08:14.70572408:00User@Host:@Id:Schema:sentrymetaLast_errno:0Killed:0Query_time:0.315758Lock_
Wesley13 Wesley13
3年前
Java异常架构
Java异常简介Java异常是Java提供的一种识别及响应错误的一致性机制。Java异常机制可以使程序中异常处理代码和正常业务代码分离,保证程序代码更加优雅,并提高程序健壮性。在有效使用异常的情况下,异常能清晰的回答what,where,why这3个问题:异常类型回答了“什么”被抛出,异常堆栈跟踪回答了“在哪“抛出,异常信息
小万哥 小万哥
7个月前
C++ 异常处理机制详解:轻松掌握异常处理技巧
C异常处理C异常处理机制允许程序在运行时处理错误或意外情况。它提供了捕获和处理错误的一种结构化方式,使程序更加健壮和可靠。异常处理的基本概念:异常:程序在运行时发生的错误或意外情况。抛出异常:使用throw关键字将异常传递给调用堆栈。捕获异常:使用
京东云开发者 京东云开发者
4个月前
引入JaCoCo导致的类型转换问题分析
一、问题描述JaCoCo是一款被广泛应用于公司内部的开源覆盖率工具,将其引用至测试环境后,机器启动正常,但在操作下单时出现异常,阻塞下单流程。去除JaCoCo配置、重新编译和部署后下单功能恢复正常。堆栈信息显示,问题源于系统对请求字段进行加密时出现异常,因
京东云开发者 京东云开发者
4星期前
大促系统优化之应用启动速度优化实践
作者:京东零售宋维飞一、前言本文记录了在大促前针对SpringBoot应用启动速度过慢而采取的优化方案,主要介绍了如何定位启动速度慢的阻塞点,以及如何解决这些问题。希望可以帮助大家了解如何定位该类问题以及提供一些解决此类问题的思路。下文介绍的JSF为京东内