JVM定位线上问题

参考

PDF教程《Java线上问题定位》，学习大纲。
PDF内容与如下博客基本一致：
https://blog.csdn.net/GitChat/article/details/79019454

核心思路

实际上是借助一堆工具（MAT、火焰图）与方法（top/jps-》jstack-》jmap）去获取信息、定位问题，背后的核心还是Jvm那一套东西，无外乎如下几种：CPU占用率过高（低效率代码问题）、高内存占用、高内存导致full gc导致stw（程序无力响应其他内容）、磁盘空间占满等的IO问题等。

表现为系统异常与业务异常：
常见的系统异常现象包括: CPU 占用率过高、CPU 上下文切换频率次数较高、磁盘满了、磁盘 I/O 过于频繁、网络流量异常 (连接数过多)、系统可用内存长期处于较低值 (导致 oom killer) 等等。这些问题可以通过 top(cpu)、free(内存)、df(磁盘)、dstat(网络流量)、pstack、vmstat、strace(底层系统调用) 等工具获取系统异常现象数据。此外，如果对系统以及应用进行排查后，均未发现异常现象的根本原因，那么也有可能是外部基础设施如 IAAS 平台本身引发的问题。

常见的业务服务异常现象包括: PV 量过高、服务调用耗时异常、线程死锁、多线程并发问题、频繁进行 Full GC、异常安全攻击扫描等。

定位流程

详见PDF第三章，排查顺序：

1. 业务⽇志分析排查
2. APM分析排查（多服务调用之间的trace-id log链路）
3. 外部环境排查（各种Linux命令以及查看对应的指标）
4. 应⽤服务排查（JVM + Arthas）
5. 云⼚商或运营商问题排查

本文主要介绍JVM排查

JVM核心排查步骤

参考：https://blog.csdn.net/benpaozaicaoyuan/article/details/107654026

1. top/jps -ml：查看所有进程占系统CPU的排序。极大可能排第一个的就是咱们的java进程（COMMAND列）。PID那一列就是进程号。
2. top -Hp 进程号：查看java进程下的所有线程占CPU的情况，从中找到目标线程。
3. printf “%x\n” 目标线程号：后续查看线程堆栈信息展示的都是十六进制，为了找到线程堆栈信息，需要把线程号转成16进制。
4. jstack 进程号 | grep 线程ID ： 查找某进程下-》具体线程ID的线程堆栈信息。
   查找信息显示为“Thread-name" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable”，第一个双引号是线程名，如果显示是“VM Thread”这就是虚拟机GC回收线程了
5. jstat -gcutil 进程号 统计间隔毫秒 统计次数（缺省代表一直统计）：查看某进程GC持续变化情况。https://www.cnblogs.com/yjmyzz/p/7478266.html
   如果发现返回中FGC时间很长且一直增大-》确认引发原因是Full GC!
6. jmap -heap 进程ID：查看一下进程的堆内存是不是要溢出了，特别是老年代内存使用情况，一般达到阈值(具体看垃圾回收器和启动时配置的阈值)就会Full GC。
7. jmap -dump:format=b,file=/path/heap.bin 进程ID ：导出某进程下内存heap输出到文件中。可以通过MAT工具查看内存中有哪些对象比较多。

步骤1-4可以简化为 ./show-busy-java-threads（https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#beer-show-busy-java-threadssh）
这个脚本来自于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 <要显示的线程栈数>

JVM几个排查例子

内存消耗过大，导致Full GC次数过多

执行步骤1-5：

• 步骤2：多个线程的CPU都超过了100%，通过jstack命令可以看到这些线程主要是垃圾回收线程。
• 步骤5：通过jstat命令监控GC情况，可以看到Full GC次数非常多，并且次数在不断增加。

确定是Full GC,接下来找到具体原因：

• 生成大量的对象，导致内存溢出-》执行步骤6，分析查看具体内存对象占用情况。
• 内存占用不高，但是Full
  GC次数还是比较多，此时可能是代码中手动调用 System.gc()导致GC次数过多，这可以通过添加
  -XX:+DisableExplicitGC来禁用JVM对显示GC的响应。

GC 原因及定位

其他Full GC问题：https://ricstudio.top/archives/java-online-question-probe
定位方法
方法a : 查看gc 日志
方法b : jstat -gcutil 进程号 统计间隔毫秒 统计次数
方法c : 如果所在公司有对应用进行监控的组件当然更方便（比如Prometheus + Grafana）
获取到gc日志之后，可以上传到GC easy帮助分析，得到可视化的图表分析结果。

prommotion failed

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

可能原因：

1. survivor 区太小，对象过早进入老年代
   查看 SurvivorRatio 参数
2. 大对象分配，没有足够的内存
   dump 堆，profiler/MAT 分析对象占用情况
3. old 区存在大量对象
   dump 堆，profiler/MAT 分析对象占用情况

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

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

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

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

GC日志理解

不同的垃圾回收器有不同的日志，看生产环境。
新年代：
ParNew：PDF第七节

老年代：
CMS回收器：参考PDF的第七节

代码中有大量消耗CPU的操作，导致CPU过高，系统运行缓慢

执行步骤1-4：在步骤4jstack，可直接定位到代码行。例如某些复杂算法，甚至算法BUG，无限循环递归等等。

由于锁使用不当，导致死锁。

执行步骤1-4： 如果有死锁，会直接提示。关键字：deadlock.步骤四，会打印出业务死锁的位置。
造成死锁的原因：最典型的就是2个线程互相等待对方持有的锁。

随机出现大量线程访问接口缓慢。

代码某个位置有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的；平时消耗的CPU不多，而且占用的内存也不高。
思路：
首先找到该接口，通过压测工具不断加大访问力度，大量线程将阻塞于该阻塞点。
执行步骤1-4：

"http-nio-8080-exec-4" #31 daemon prio=5 os_prio=31 tid=0x00007fd08d0fa000 nid=0x6403 waiting on condition [0x00007000033db000]

   java.lang.Thread.State: TIMED_WAITING (sleeping)-》期限等待

    at java.lang.Thread.sleep(Native Method)

    at java.lang.Thread.sleep(Thread.java:340)

    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)

    at com.*.user.controller.UserController.detail(UserController.java:18)-》业务代码阻塞点

如上图，找到业务代码阻塞点，这里业务代码使用了TimeUnit.sleep()方法，使线程进入了TIMED_WAITING(期限等待)状态。

CPU使用率高

CPU 使用率高问题定位

按照定位流程首先排除了系统层面的问题。
利用 top -Hp 6814 输出进程 ID 为 6814 的所有线程 CPU 使用率情况，发现某个线程使用率比较高，有些异常。

printf '%x\n' 2304     #输出线程 ID 的 16 进制
jstack pid | grep '0x900' -C 30 --color

输出的日志表明该线程一直处于与 mysql I/O 状态：

利用 jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid} 以二进制输出档当前内存的堆情况，然后可以导入 MAT 等工具进行分析。
如下图所示，点击 MAT 的支配树可以发现存在某个超大对象数组，实例对象数目多大 30 多万个。

经过分析发现数组中每一个对象都是核心业务对象，我们的业务系统有一个定时任务线程会访问数据库某张业务表的所有记录。
然后加载至内存然后进行处理因此内存吃紧，导致 CPU 突然飙升。发现该问题后，已对该方案进行重新设计。

磁盘空间不足导致IO阻塞

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

线程池异常

https://ricstudio.top/archives/java-online-question-probe

场景预设：业务监控突然告警，或者外部反馈提示大量请求执行失败。

异常说明：

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

常见问题和原因

这种线程池异常，一般可以通过开发查看日志查出原因，有以下几种原因：

1. 下游服务 响应时间（RT）过长

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

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

2. 数据库慢 sql 或者数据库死锁，查看日志中相关的关键词。

3. Java 代码死锁
   jstack –l pid | grep -i –E ‘BLOCKED | deadlock’

redis 大key引发CPU100%

什么情况下会导致redis的cpu飙升到100%：

redis从库大批量同步到redis主库
redis请求的qps过高
redis存在大量慢查询

https://cloud.tencent.com/developer/article/1582323?from=article.detail.1546726

其他JVM方法

jmap

输出说明以及堆内存实例

详见：https://www.cnblogs.com/yjmyzz/p/7478266.html

磁盘、CPU、GC、内存、网络、redis、MySQL等各种问题示例帖子

https://www.infoq.cn/article/qisvv7sfrsxmikhldvtw