hello 宝儿们 周末好
我是京东码农小哥 ──可爱猪猪
不知道 618 剁手或者护航的你是否有新的收获？
那么今天和大家聊聊一个话题 ──JVM 困局的攻与破
JVM 实践对于很多新手来说有点挠破头皮、无从下手的感觉
总觉得是一座迈不过去的大山
不过，不要紧，以后遇到 JVM 实践上的问题与困扰
不妨先收藏这篇文章或许能够帮助到工作中漫无头绪的你
JVM 实践有特定的方法论，读完这篇文章你将有以下收获：
- http 接口超时的常见排查思路及方法
- JVM 内存&垃圾回收常用实践命令
- 系统 CPU 飙高与资源消耗的线程定位
- 如何分析 JVM 线程堆栈日志和内存 Dump
- Excel 文件导出与下载的正确姿势
- 客户端与MQ连接超时的是是非非
以下文章阅读预计需要 15 分钟，目录:
- 是什么导致接口超时? * 发现问题，初步诊断
- 根据初诊，进而确认
- 揭开真相的面纱
- CPU何故飙升? * 起飞的 CPU，永不止步
- 找到幕后的线程
- JVM堆栈信息
- 线程与JVM堆栈信息
- 剖析JVM堆栈信息
- 繁忙的垃圾回收器? * 监控垃圾回收
- Who侵蚀了JVM的内存？
- JVM堆栈信息
- Excel导出工具选择？
- 并发症：链接MQ异常，为何？
- 总结
是什么导致接口超时？
其实每个程序员都是
名侦探柯南,通过蛛丝马迹牵出大案件，今天要和大家分享一个接口超时与JVM之间的故事
- 发现问题，初步诊断
测试反应线上出现接口超时，根据经验，这种情况 80%由 SQL 语句慢、锁等待、代码阻塞、长任务执行等引起的接口执行时间超出了 http 请求的超时时间所致。
以下是浏览器定时发起该接口的 http 请求，短则毫秒级响应、长则 3、5 秒乃至超时。
- 根据初诊，进而确认
遇到这种情况，例行检查代码，找到性能低的 SQL 语句或者代码进行调优基本可以解决同类问题。
于是，便查看超时接口getTaskStatus的实现逻辑：
public DownloadTaskInfo getTaskStatus(String taskId) {
DownloadTaskInfo taskInfo;
// 1.获取redis中任务的状态
String taskInfoStr = redisUtil.get(taskId);
if (taskInfoStr == null) {
taskInfo = new DownloadTaskInfo();
taskInfo.setTaskId(taskId);
taskInfo.setStatus(DownloadTaskStatusEnum.NOT_START.getCode());
return taskInfo;
}
return JSONUtil.toBean(taskInfoStr, DownloadTaskInfo.class);
}
该接口是前端每 4 秒请求导出任务的执行状态，然而并没有发现 SQL 语句，所以排除掉 SQL 性能所致， 唯一可疑点:redisUtil.get(taskId)访问 redis 超时？难不成前端 4 秒请求一次 redis 把 redis 服务器性能拉低了？ 或者 redis 服务被其他应用（该 redis 多应用公用）使用导致服务器性能下降？ 排查各个 redis 服务器各项指标、日志都是正常的，排查掉唯一可能由代码或者数据库导致接口超时的原因
-
揭开真相的面纱
宝儿们，是不是跟我一样排查到此，突然有种思路 Offline 的感觉？
不知道你在使用 Windows 系统的时候是不是有遇到过电脑 CPU 超过 90%,连打开一个文件夹都特别慢呢？
咦？难道是服务器 CPU 所致？我们都知道 CPU 通过分配时间片来工作，接口调用过来需要 CPU 来处理，如果 CPU 繁忙，那么新进来的任务只有等待...
CPU 何故飙升？
- 起飞的 CPU，永不止步
为了重现问题，点击了系统的[导出]按钮，浏览器再次发起了getTaskStatus 接口的定时调用，红框内为 CPU 的状态：持续飙升~
- 找到幕后的线程
CPU占用与线程的执行是密切相关的，只有找到真正忙碌的线程，找到线程的最终目的是分析出有问题的代码或者任务！
那么问题来了？通过什么样的手段或者方法才能找到Top线程呢？其实很简单，执行以下命令：
#1.查找Java进程Id
[admin@my-linux~]$ jps
20704 Jps
48172 Application
#2.根据进程ID，统计top线程
[admin@my-linux~]$ top -Hp 48172
linux top线程命令,执行结果如图：
该图反应了几项重要的信息:
列表中线程CPU占用排行由高到低排列。
每一行信息中有内存占比、CPU占比等关键信息。
对我来说非常重要的一列：PID(线程ID)。通过PID我们可以找到对应JVM线程堆栈信息。
-
JVM堆栈信息
什么是JVM堆栈信息？有什么用？又如何查看呢？
执行jvm命令查看JVM堆栈信息：
[admin@my-linux~]$ jstack 48172
JVM堆栈信息是线程运行时的执行状态，以下为堆栈日志的快照：
<pre class="custom" style="margin-top: 10px; margin-bottom: 10px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">`"pool-10-thread-101" #1997 prio=5 os_prio=0 tid=0x00007fc88c0d5800 nid=0xc691 waiting on condition [0x00007fbb3608a000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000083e37320> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:924)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)` </pre>
堆栈信息包含：
线程名称、状态、执行的代码链路、线程的ID对应十六进制等它主要目的是定位线程出现长时间停顿的原因，如
线程间死锁、死循环、请求外部资源导致的长时间等待等。-
线程与JVM堆栈信息
通过
top -Hp命令我们找到top线程ID排行,那如何通过线程ID从JVM堆栈信息中定位到该信息呢？首先，将线程ID转换为16进制，比如上图中，占用最高的线程Id:
48391和51012，转换后分别为bd07和c744：
其次，将转换后的16进制在JVM堆栈信息中进行搜索。
- 剖析JVM堆栈信息
线程Id:51012->c744,堆栈信息如下：
"pool-11-thread-1" #2039 prio=5 os_prio=0 tid=0x00007fbbfc057800 nid=0xc744 runnable [0x00007fbb35565000]
java.lang.Thread.State: RUNNABLE
at com.xxxx.utils.excel.Excel.setSheetBody(Excel.java:223)
at com.xxxx.utils.excel.Excel.toXSSFWorkbook(Excel.java:130)
at com.xxxx.utils.excel.Excel.writeOutput(Excel.java:82)
at com.xxxx.utils.excel.Excel.getExcelBytes(Excel.java:99)
该代码逻辑是执行excel数据拼装，属于正常线程占用。
而，线程Id:48391->bd07,堆栈信息如下：
"Gang worker#8 (G1 Parallel Marking Threads)" os_prio=0 tid=0x00007fcf8c1dd800 nid=0xbd07 runnable
G1垃圾回收器线程正在进行并行标记。同时在其他几个top线程工作内容也是垃圾回收相关，如下图：
由此可见，CPU飙升的根本原因是因为垃圾回收器线程一直在工作导致，我们的排查目标从CPU转移到了内存。
繁忙的垃圾回收器
- 监控垃圾回收
既然JVM堆栈信息中有很多G1垃圾回收线程的工作日志，那是不是垃圾回收期真的如此繁忙的工作呢？我们使用JVM命令来监控一下吧。
[admin@my-linux~]$ jstat -gcutil 48172 1000 100
以下截图，一行即每一秒的内存状况：
- E：代表新生代Eden区的空间占用比
- YGC：代表新生代的垃圾回收次数
因此，我们可以快速判断，Eden区非常快就占满，几乎1~3秒就会触发一次垃圾回收。实锤了，就是疯狂的垃圾回收导致CPU持续飙升。
- Who侵蚀了JVM的内存？
为了弄清楚这个原因，我们不得不使用Java的另一条风神令：jmap。
[admin@my-linux~]$ jmap -dump:format=b,file=m.dump 48172
通过jmap导出了JVM内存的dump文件，用于JVM内存分析。文件可能会比较大，所以最好准备一个稍微大一点的目录位置来存储。
有了dump文件，我们怎么进行分析呢？这时候需要借助另外一个客户端工具：Memory Analyzer Tool,可以百度自行下载。
导入dump文件，工具会自动分析内存的情况，下图1.8GB是可疑内存：
Leak suspects查看内存占用详情
大部分都是poi相关的类，也就是引入的excel工具，百度发现poi的XSSF的数据组装全部在内存，如果导出的数据比较多，内存会一直持续上升。
Excel导出工具选择？
由于使用poi的XSSF，所有数据在全部在内存中进行处理，如果数据量大，将会占用极高的内存。
因此，推荐大家使用EasyExcel,EasyExcel是一个基于Java的简单、省内存的读写Excel的开源项目。在尽可能节约内存的情况下支持读写百M的Excel
并发症：链接MQ异常，为何？
基于以上的分析，发现内存使用不释放导致垃圾回收器线程繁忙工作，进而CPU使用率比较高。间接导致接口超时等现象。
线程无法获取到CPU时间片，同样也会引发其他的并发症：与MQ等中间件链接异常。 一些中间件和Client端通过心跳机制维持链接状态。如果Server端在指定超时时间内未收到心跳。会造成链接异常、超时等并发问题。
总结
今天，由一个接口超时，逐步排查到CPU、JVM内存、Excel工具，逐步分析出问题的根因。
工欲善其事，必现利其器。jstat、jstack、jmap、top、MAT等命令和工具辅助我们分析问题起到了重要作用。
同时，内存异常也可能导致一系列的并发症。
今天文章比较长，如果你都看到了这里，给可爱猪猪点个赞或者在看。
好了，今天就聊到这里，我是可爱猪猪，下篇文章再会！
