《Dubbo 实现原理与源码解析 —— 精品合集》 《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》 《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》 《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》 《Java 面试题 + Java 学习指南》

摘要: 原创出处 ricstudio.top/archives/java-online-question-prob 「Richard_Y」欢迎转载,保留摘要,谢谢!


🙂🙂🙂关注微信公众号:【芋道源码】有福利:

  1. RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表
  2. RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址
  3. 您对于源码的疑问每条留言将得到认真回复。甚至不知道如何读源码也可以请教噢
  4. 新的源码解析文章实时收到通知。每周更新一篇左右
  5. 认真的源码交流微信群。

前言

本文总结了一些Java应用线上常见问题的定位步骤,分享的主要目的是想让对线上问题接触少的同学有个预先认知,免得在遇到实际问题时手忙脚乱。毕竟作者自己也是从手忙脚乱时走过来的。

只不过这里先提示一下。在线上应急过程中要记住,只有一个总体目标:「尽快恢复服务,消除影响」 。不管处于应急的哪个阶段,我们首先必须想到的是恢复问题,恢复问题不一定能够定位问题,也不一定有完美的解决方案,也许是通过经验判断,也许是预设开关等,但都可能让我们达到快速恢复的目的,然后保留部分现场,再去定位问题、解决问题和复盘。

好,现在让我们进入正题吧。

一、CPU 利用率高/飙升

注:CPU使用率是衡量系统繁忙程度的重要指标。但是「CPU使用率的安全阈值是相对的,取决于你的系统的IO密集型还是计算密集型」 。一般计算密集型应用CPU使用率偏高load偏低,IO密集型相反。

「常见原因:」

  • 频繁 gc
  • 死循环、线程阻塞、io wait…etc

模拟

这里为了演示,用一个最简单的死循环来模拟CPU飙升的场景,下面是模拟代码,

在一个最简单的SpringBoot Web 项目中增加CpuReaper这个类,

/**
* 模拟 cpu 飙升场景
* @author Richard_yyf
*/
@Component
public class CpuReaper {

@PostConstruct
public void cpuReaper() {
int num = 0;
long start = System.currentTimeMillis() / 1000;
while (true) {
num = num + 1;
if (num == Integer.MAX_VALUE) {
System.out.println("reset");
num = 0;
}
if ((System.currentTimeMillis() / 1000) - start > 1000) {
return;
}
}
}
}

打包成jar之后,在服务器上运行。java -jar cpu-reaper.jar &

第一步:定位出问题的线程

方法 a: 传统的方法

  1. top 定位CPU 最高的进程

    执行top命令,查看所有进程占系统CPU的排序,定位是哪个进程搞的鬼。在本例中就是咱们的java进程。PID那一列就是进程号。(对指示符含义不清楚的见【附录】)

  2. top -Hp pid 定位使用 CPU 最高的线程

  3. printf '0x%x' tid 线程 id 转化 16 进制

> printf '0x%x' 12817
> 0x3211
  1. jstack pid | grep tid 找到线程堆栈
> jstack 12816 | grep 0x3211 -A 30

方法 b: show-busy-java-threads

https://raw.github.com/oldratlee/useful-scripts/release-2.x/bin/show-busy-java-threads

这个脚本来自于github上一个开源项目,项目提供了很多有用的脚本,show-busy-java-threads就是其中的一个。使用这个脚本,可以直接简化方法A中的繁琐步骤。如下,

> wget --no-check-certificate https://raw.github.com/oldratlee/useful-scripts/release-2.x/bin/show-busy-java-threads
> chmod +x show-busy-java-threads

> ./show-busy-java-threads

show-busy-java-threads
# 从所有运行的Java进程中找出最消耗CPU的线程(缺省5个),打印出其线程栈

# 缺省会自动从所有的Java进程中找出最消耗CPU的线程,这样用更方便
# 当然你可以手动指定要分析的Java进程Id,以保证只会显示你关心的那个Java进程的信息
show-busy-java-threads -p <指定的Java进程Id>

show-busy-java-threads -c <要显示的线程栈数>

方法 c: arthas thread

阿里开源的arthas现在已经几乎包揽了我们线上排查问题的工作,提供了一个很完整的工具集。在这个场景中,也只需要一个thread -n命令即可。

https://github.com/alibaba/arthas

> curl -O https://arthas.gitee.io/arthas-boot.jar # 下载

要注意的是,arthas的cpu占比,和前面两种cpu占比统计方式不同。前面两种针对的是Java进程启动开始到现在的cpu占比情况,arthas这种是一段采样间隔内,当前JVM里各个线程所占用的cpu时间占总cpu时间的百分比。

具体见官网:https://alibaba.github.io/arthas/thread.html

后续

通过第一步,找出有问题的代码之后,观察到线程栈之后。我们「就要根据具体问题来具体分析」 。这里举几个例子。

情况一:发现使用CPU最高的都是GC 线程。

GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fd99001f800 nid=0x779 runnable
GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fd990021800 nid=0x77a runnable
GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fd990023000 nid=0x77b runnable
GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fd990025000 nid=0x77c runnabl

gc 排查的内容较多,所以我决定在后面单独列一节讲述。

情况二:发现使用CPU最高的是业务线程

  • io wait

    • 比如此例中,就是因为磁盘空间不够导致的io阻塞

https://blog.csdn.net/lonyness/article/details/82628988

  • 等待内核态锁,如 synchronized

    • jstack -l pid | grep BLOCKED 查看阻塞态线程堆栈
    • dump 线程栈,分析线程持锁情况。
    • arthas提供了thread -b,可以找出当前阻塞其他线程的线程。针对 synchronized 情况

二、频繁 GC

1. 回顾GC流程

在了解下面内容之前,请先花点时间回顾一下GC的整个流程。


接前面的内容,这个情况下,我们自然而然想到去查看gc 的具体情况。

  • 方法a : 查看gc 日志
  • 方法b : jstat -gcutil 进程号 统计间隔毫秒 统计次数(缺省代表一致统计
  • 方法c : 如果所在公司有对应用进行监控的组件当然更方便(比如Prometheus + Grafana)

这里对开启 gc log 进行补充说明。一个常常被讨论的问题(惯性思维)是在生产环境中GC日志是否应该开启。因为它所产生的开销通常都非常有限,因此我的答案是需要「开启」 。但并不一定在启动JVM时就必须指定GC日志参数。

HotSpot JVM有一类特别的参数叫做可管理的参数。对于这些参数,可以在运行时修改他们的值。我们这里所讨论的所有参数以及以“PrintGC”开头的参数都是可管理的参数。这样在任何时候我们都可以开启或是关闭GC日志。比如我们可以使用JDK自带的jinfo工具来设置这些参数,或者是通过JMX客户端调用HotSpotDiagnostic MXBean的setVMOption方法来设置这些参数。

这里再次大赞arthas❤️,它提供的vmoption命令可以直接查看,更新VM诊断相关的参数。

获取到gc日志之后,可以上传到GC easy帮助分析,得到可视化的图表分析结果。

http://gceasy.io/

2. GC 原因及定位

「prommotion failed」

从S区晋升的对象在老年代也放不下导致 FullGC(fgc 回收无效则抛 OOM)。

可能原因:

  • 「survivor 区太小,对象过早进入老年代」

    查看 SurvivorRatio 参数

  • 「大对象分配,没有足够的内存」

    dump 堆,profiler/MAT 分析对象占用情况

  • 「old 区存在大量对象」

    dump 堆,profiler/MAT 分析对象占用情况

你也可以从full GC 的效果来推断问题,正常情况下,一次full GC应该会回收大量内存,所以 「正常的堆内存曲线应该是呈锯齿形」 。如果你发现full gc 之后堆内存几乎没有下降,那么可以推断:「堆中有大量不能回收的对象且在不停膨胀,使堆的使用占比超过full GC的触发阈值,但又回收不掉,导致full GC一直执行。\ 「换句话来说,可能是」**内存泄露」** 了。

一般来说,GC相关的异常推断都需要涉及到「内存分析」 ,使用jmap之类的工具dump出内存快照(或者 Arthas的heapdump)命令,然后使用MAT、JProfiler、JVisualVM等可视化内存分析工具。

至于内存分析之后的步骤,就需要小伙伴们根据具体问题具体分析啦。

三、线程池异常

Java 线程池以有界队列的线程池为例,当新任务提交时,如果运行的线程少于 corePoolSize,则创建新线程来处理请求。如果正在运行的线程数等于 corePoolSize 时,则新任务被添加到队列中,直到队列满。当队列满了后,会继续开辟新线程来处理任务,但不超过 maximumPoolSize。当任务队列满了并且已开辟了最大线程数,此时又来了新任务,ThreadPoolExecutor 会拒绝服务。

常见问题和原因

这种线程池异常,一般有以下几种原因:

  1. 「下游服务 响应时间(RT)过长」

    这种情况有可能是因为下游服务异常导致的,作为消费者我们要设置合适的超时时间和熔断降级机制。

    另外针对这种情况,一般都要有对应的监控机制:比如日志监控、metrics监控告警等,不要等到目标用户感觉到异常,从外部反映进来问题才去看日志查。

  2. 「数据库慢 sql 或者数据库死锁」

查看日志关键词

  1. 「Java 代码死锁」

    jstack –l pid | grep -i –E 'BLOCKED | deadlock'

上述前两种问题的排查办法,一般都是通过查看日志或者一些监控组件。

四、常见问题恢复

这一部分内容参考自此篇文章

https://developer.aliyun.com/article/757655

五、Arthas

这里还是想单独用一节安利一下Arthas这个工具。

Arthas 是阿里巴巴开源的Java 诊断工具,基于 Java Agent 方式,使用 Instrumentation 方式修改字节码方式进行 Java 应用诊断。

  • dashboard :系统实时数据面板, 可查看线程,内存,gc 等信息
  • thread :查看当前线程信息,查看线程的堆栈,如查看最繁忙的前 n 线程
  • getstatic:获取静态属性值,如 getstatic className attrName 可用于查看线上开关真实值
  • sc:查看 jvm 已加载类信息,可用于排查 jar 包冲突
  • sm:查看 jvm 已加载类的方法信息
  • jad:反编译 jvm 加载类信息,排查代码逻辑没执行原因
  • logger:查看logger信息,更新logger level
  • watch:观测方法执行数据,包含出参、入参、异常等
  • trace:方法内部调用时长,并输出每个节点的耗时,用于性能分析
  • tt:用于记录方法,并做回放

以上内容节选自Arthas官方文档。

https://alibaba.github.io/arthas/commands.html

另外,Arthas 里的 还集成了 ognl 这个轻量级的表达式引擎,通过ognl,你可以用arthas 实现很多的“骚”操作。

其他的这里就不多说了,感兴趣的可以去看看arthas的官方文档、github issue。

六、涉及工具

再说下一些工具。

  • Arthas(超级推荐❤️❤️)
  • useful-scripts
  • GC easy
  • Smart Java thread dump analyzer - thread dump analysis in seconds
  • PerfMa - Java虚拟机参数/线程dump/内存dump分析
  • Linux 命令
  • Java N 板斧
  • MAT、JProfiler…等可视化内存分析工具

结语

我知道我这篇文章对于线上异常的归纳并不全面,还有「网络(超时、TCP队列溢出…)」 、堆外内存等很多的异常场景没有涉及。主要是因为自己接触很少,没有深刻体会研究过,强行写出来免不得会差点意思,更怕的是误了别人😅。

还有想说的就是,Java 应用线上排查实际非常考究一个人基础是否扎实、解决问题能力是否过关。比如线程池运行机制、gc分析、Java 内存分析等等,如果基础不扎实,看了更多的是一头雾水。另外就是,多看看网上一些好的关于异常排查的经验文章,这样即使自己暂时遇不到,但是会在脑海里面慢慢总结出一套解决类似问题的结构框架,到时候真的遇到了,也就是触类旁通的事情罢了。

如果本文有帮助到你,希望能点个赞,这是对我的最大动力🤝🤝🤗🤗。

参考

附录

top 命令显示的指示符的含义

指示符 含义
PID 进程id
USER 进程所有者
PR 进程优先级
NI nice值。负值表示高优先级,正值表示低优先级
VIRT 进程使用的虚拟内存总量,单位kb。VIRT=SWAP+RES
RES 进程使用的、未被换出的物理内存大小,单位kb。RES=CODE+DATA
SHR 共享内存大小,单位kb
S 进程状态。D=不可中断的睡眠状态 R=运行 S=睡眠 T=跟踪/停止 Z=僵尸进程
%CPU 上次更新到现在的CPU时间占用百分比
%MEM 进程使用的物理内存百分比
TIME+ 进程使用的CPU时间总计,单位1/100秒
COMMAND 进程名称(命令名/命令行)
文章目录
  1. 1. 前言
  2. 2. 一、CPU 利用率高/飙升
    1. 2.1. 模拟
    2. 2.2. 第一步:定位出问题的线程
      1. 2.2.1. 方法 a: 传统的方法
      2. 2.2.2. 方法 b: show-busy-java-threads
      3. 2.2.3. 方法 c: arthas thread
    3. 2.3. 后续
      1. 2.3.1. 情况一:发现使用CPU最高的都是GC 线程。
      2. 2.3.2. 情况二:发现使用CPU最高的是业务线程
  3. 3. 二、频繁 GC
    1. 3.1. 1. 回顾GC流程
    2. 3.2. 2. GC 原因及定位
  4. 4. 三、线程池异常
    1. 4.1. 常见问题和原因
  5. 5. 四、常见问题恢复
  6. 6. 五、Arthas
  7. 7. 六、涉及工具
  8. 8. 结语
  9. 9. 参考
  10. 10. 附录
    1. 10.1. top 命令显示的指示符的含义