共计 2729 个字符，预计需要花费 7 分钟才能阅读完成。
欢迎大家前往腾讯云 + 社区，获取更多腾讯海量技术实践干货哦~
本文由净地发表于云 + 社区专栏记一次 Java 线上服务器 CPU 过载问题的排查过程，详解排查过程中用到的 Java 性能监测工具：jvisualvm、jstack、jstat、jmap。
背景：Java 线上服务运行一周后，某个周六晚上 CPU 使用率突然持续 99%，Java 进程处于假死状态，不响应请求。秉着先恢复服务再排查问题的原则，在我连接 VPN 采用重启大法后，CPU 使用率恢复正常，服务也正常响应了，如下图一所示：
（图一）CPU 使用率图
但是，当晚的并发量也没有比平时高出许多，为什么会突然出现这种 CPU 爆表的情况？带着这个疑问，我走上了问题排查的道路。
首先，我查了相关的错误日志，发现故障的时间段内有大量的 ckv 请求超时，但请求超时并不是 ckv server 的问题，而是 ckv client 的请求并没有发出去。那么，为什么 ckv client 的请求没有发出去呢？日志并没有提供更多的信息给我。
于是，我在 Java 服务上开启了 JMX，本地采用 jvisualvm 来观察 Java 进程运行时的堆栈内存、线程使用情况。JMX（Java Management Extensions，即 Java 管理扩展）是 Java 平台上为应用程序、设备、系统等植入管理功能的框架；jvisualvm 是 JDK 内置的性能分析工具，位于 JDK 根目录的 bin 文件夹下面，它可以通过 JMX 从 Java 程序获取运行时的实时数据，从而进行动态的性能分析，如图二所示：
（图二）jvisualvm
通过观察 Heap 内存的使用情况，发现其是缓慢增加的，每隔一小段时间被 GC 回收，图形呈锯齿状，似乎没有什么问题；Threads 也没有存在死锁的问题，线程运行良好；在 Sampler 查看 Thread CPU Time 的时候发现，log4j 的异步日志线程占用的 CPU 时间是最多的。于是，初步怀疑这是 log4j 的锅。接着，我对项目代码进行了 review，发现某些接口打印了大量的无用日志，日志级别使用也不规范。最后，我对项目的日志进行了整体的梳理，优化后发布上线，并继续观察。
我本以为问题已经解决了。然而，几天后又出现了 CPU 爆表的情况，这时，我才发现自己错怪了 log4j。与上次爆表的情况不同，这次我在公司（表示很淡定），于是我机智地保留了一台机器来做观察，其他机器做重启处理。现在，要开始我的表演了，具体如下：
（1）登陆机器，用 top 命令查看进程资源占用情况。不出所料，Java 进程把 CPU 撑爆了，如下图三所示：
（图三）进程资源占用情况
（2）Java 进程把 CPU 都占用完了，那么具体是进程内的哪些线程占用的呢？于是，我用了 top -H -p6902（6902 是 Java 进程的 PID）命令找出了具体的线程资源占用情况，如下图四所示：
（图四）Java 线程资源占用情况
图四中的 PID 为 Java 线程的 id，可以看到 id 为 6904、6905、6906、6907 这四个线程基本把 CPU 资源全部吃完了。
（3）现在，我们已经拿到耗尽 CPU 资源的线程 id 了。这时，我们就可以使用 jstack 来查找这些 id 对应的具体线程堆栈信息了。jstack 是 JDK 内置的堆栈跟踪工具，位于 JDK 根目录的 bin 文件夹下面，可用于打印的 Java 堆栈信息。我用命令 jstack 6902 > jstack.txt（6902 是 Java 进程的 PID）打印出了 Java 进程的堆栈信息放到 jstack.txt 文件了；由于堆栈打印的线程的 native id 是十六机制的，所以，我把十进制的线程 id（6904、6905、6906、6907）转化成十六进制（0x1af8、0x1af9、0x1afa、0x1afb）；最后，通过 cat jstack.txt | grep -C 20 0x1af8 命令找到了具体的线程信息，如下图五所示：
（图五）线程堆栈信息
通过图五可以发现，把 CPU 占满的线程是 GC 的线程，Java 的垃圾回收把 CPU 的资源耗尽了。
（4）现在，我们已经定位到是 GC 的问题了。那么，我们就来看看 GC 的回收情况，我们可以通过 jstat 来观察。jstat 是 JDK 内置的 JVM 检测统计工具，位于 JDK 根目录的 bin 文件夹下面，可以对堆内存的使用情况进行实时统计。我使用了命令 jstat -gcutil 6902 2000 10（6902 是 Java 进程的 PID）来观察 GC 的运行信息，如下图六所示：
（图六）GC 运行信息
通过图六可以知道，E（Eden 区）跟 O（Old 区）的内存已经被耗尽了，FGC（Full GC）的次数高达 6989 次，FGCT（Full GC Time）的时间高达 36453 秒，即平均每次 FGC 的时间为：36453/6989 ≈ 5.21 秒。也就是说，Java 进程都把时间花在 GC 上了，所以就没有时间来处理其他事情。
（5）GC 出现图六的这种情况，基本可以确认是在程序中存在内存泄露的问题。那么，如何确定是哪些代码导致的这个问题呢？这时候，我们就可以使用 jmap 查看 Java 的内存占用信息。jmap 是 JDK 内置的内存映射工具，位于 JDK 根目录的 bin 文件夹下面，可用于获取 java 进程的内存映射信息。通过命令 jmap -histo 6902（6902 是 Java 进程的 PID）打印出了 Java 的内存占用信息，如下图七所示：
（图七）Java 内存占用信息
由图七可以得到，占用内存资源的 TOP10 类（[C 是指 char[]，String 类内部使用 char[] 来保存数据）的名称、实例数以及占用内存大小（单位：byte），于是问题排查就变得非常简单了。最后，通过 review 代码确定了问题所在：
部分接口使用到了 L5QOSPacket 这个 L5 的工具类没有做单例，每次请求接口都会生成一个新的实例，浪费了大量的内存。
代码里边用到的一个第三方提供的 QcClient 客户端存在内存泄露问题，代码中不恰当地 new 了大量的对象，而且对存储在 ConcurrentHashMap 的数据没有做清除清理，从而导致数据一直累计，内存占用持续增加。
解决以上两个问题后，Heap 内存的占用维持在 2.5G 左右，已经没有持续增长的迹象了，业务已正常运行。
以上就是我排查问题的整个过程，以及在这个过程中用到的一些 Java 性能监测工具。除了本文提及的 jvisualvm、jstack、jstat、jmap 这些工具，在 JDK 根目录的 bin 文件夹下面还有其他许多非常有用的工具，例如：使用 jinfo 查看 Java 进程相关信息，感兴趣的童鞋可以去研究下。
相关阅读 WCF 系列教程之 WCF 服务配置 php 异步执行黑客用 Python：检测并绕过 Web 应用程序防火墙【每日课程推荐】机器学习实战！快速入门在线广告业务及 CTR 相应知识
