Loading...
墨滴

可爱猪猪

2021/06/19  阅读:78  主题:兰青

JVM困局的攻与破:京东小哥手把手教给你5种常见的JVM杀手锏

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 秒乃至超时。

            图一:谷歌浏览器 F12,NetWork 中网络请求

  • 根据初诊,进而确认

遇到这种情况,例行检查代码,找到性能低的 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 的状态:持续飙升~                       图二:Docker 容器的 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线程命令

执行结果如图:

                                  图三:top线程列表

该图反应了几项重要的信息:

  • 列表中线程CPU占用排行由高到低排列。

  • 每一行信息中有内存占比、CPU占比等关键信息。

  • 对我来说非常重要的一列:PID(线程ID)。通过PID我们可以找到对应JVM线程堆栈信息。

  • JVM堆栈信息

    什么是JVM堆栈信息?有什么用?又如何查看呢?

    执行jvm命令查看JVM堆栈信息:

    [admin@my-linux~]$ jstack 48172

    JVM堆栈信息是线程运行时的执行状态,以下为堆栈日志的快照:

    "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)

                                    JVM堆栈信息示例

  • 堆栈信息包含:线程名称状态执行的代码链路线程的ID对应十六进制

  • 它主要目的是定位线程出现长时间停顿的原因,如线程间死锁死循环请求外部资源导致的长时间等待等。

  • 线程与JVM堆栈信息

    通过top -Hp命令我们找到top线程ID排行,那如何通过线程ID从JVM堆栈信息中定位到该信息呢?

    首先,将线程ID转换为16进制,比如上图中,占用最高的线程Id:4839151012,转换后分别为bd07c744

                      图四:线程ID10进制与16进制转换

其次,将转换后的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线程工作内容也是垃圾回收相关,如下图:

                      图五:G1垃圾回收期堆栈信息

由此可见,CPU飙升的根本原因是因为垃圾回收器线程一直在工作导致,我们的排查目标从CPU转移到了内存。

繁忙的垃圾回收器

  • 监控垃圾回收

既然JVM堆栈信息中有很多G1垃圾回收线程的工作日志,那是不是垃圾回收期真的如此繁忙的工作呢?我们使用JVM命令来监控一下吧。

#每个一秒刷新一次JVM内存情况,一直刷新100次
[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查看内存占用详情

                                  图八:Leak suspects

大部分都是poi相关的类,也就是引入的excel工具,百度发现poi的XSSF的数据组装全部在内存,如果导出的数据比较多,内存会一直持续上升。

Excel导出工具选择?

由于使用poi的XSSF,所有数据在全部在内存中进行处理,如果数据量大,将会占用极高的内存。
因此,推荐大家使用EasyExcel,EasyExcel是一个基于Java的简单、省内存的读写Excel的开源项目。在尽可能节约内存的情况下支持读写百M的Excel

并发症:链接MQ异常,为何?

基于以上的分析,发现内存使用不释放导致垃圾回收器线程繁忙工作,进而CPU使用率比较高。间接导致接口超时等现象。
线程无法获取到CPU时间片,同样也会引发其他的并发症:与MQ等中间件链接异常。 一些中间件和Client端通过心跳机制维持链接状态。如果Server端在指定超时时间内未收到心跳。会造成链接异常、超时等并发问题。

总结

今天,由一个接口超时,逐步排查到CPUJVM内存Excel工具,逐步分析出问题的根因。
工欲善其事,必现利其器。jstatjstackjmaptopMAT等命令和工具辅助我们分析问题起到了重要作用。
同时,内存异常也可能导致一系列的并发症。
今天文章比较长,如果你都看到了这里,给可爱猪猪点个或者在看

好了,今天就聊到这里,我是可爱猪猪,下篇文章再会!

微信公众号”面试怪圈“记得关注哦~~

可爱猪猪

2021/06/19  阅读:78  主题:兰青

作者介绍

可爱猪猪