深入JVM：线上服务性能问题诊断思路

文章目录

深入JVM：线上服务性能问题诊断思路
- 一、序言
- 二、常见线上性能问题
- 三、诊断CPU使用率过高
- - 1、检查CPU高使用率进程
  - 2、导出线程堆栈信息
  - 3、深入识别高使用率线程
  - 4、高使用率线程信息定位
- 四、诊断服务响应时间过长
- - 1、诊断GC及内存问题
  - 2、诊断慢查询
  - - 2.1 Arthas线上诊断工具
    - - ① trace命令：调用追踪
      - ② watch命令：监控方法
      - ③ thread命令：监控线程
- 五、诊断服务运行线程耗尽
- - 1、诊断线程死锁
  - 2、线程超时等待及线程阻塞
- 六、后记

深入JVM：线上服务性能问题诊断思路

一、序言

对于Java工程师而言，深入理解JVM（Java虚拟机）不仅是掌握Java程序运行机制的基础，也是提升系统性能、优化应用和解决复杂问题能力的重要一步，更是Java进阶之路的重中之重。

对于项目来说，最终都是要上线发布，可以说我们之所以深度学习JVM，其核心就是为了保障线上服务的性能和稳定性，本文小豪将继续贴近实战，带大家定位并处理线上服务性能问题，梳理诊断思路，包括CPU使用率过高、接口响应耗时过长及线程资源耗尽等常见线上性能问题。

二、常见线上性能问题

在工作上，大家可能或多或少会碰到Java线上服务的性能问题，比如服务卡顿、响应超时等，掌握线上服务性能诊断技能，还是十分必要的，本节小豪将会通过几个应用案例，带大家梳理一下线上服务性能问题的诊断思路。

常见的线上性能问题主要包含以下三种：

CPU使用率过高：CPU使用率过高会导致程序运行卡顿，一般出现在程序进行大量计算或遇到死循环，造成任务处理效率降低
服务响应时间过长：服务响应时间过长是指从接收到请求到返回响应的时间间隔超出预期，原因较多，可能是内存不足导致频繁GC、数据库查询慢、资源等待（如等待锁），响应时间过长会直接影响用户体验
服务运行线程耗尽：服务运行线程耗尽指程序线程执行结果不正常，无法处理任务请求，可能存在线程超时等待、线程阻塞或线程死锁等情况，导致线程被耗尽，新的请求无法被正常处理，影响服务稳定性

三、诊断CPU使用率过高

一般当出现性能问题时，首要做的就是先排查是否是CPU方面出的问题，CPU过高会明显导致服务运行缓慢，接下来，我们逐步演示一下线上服务CPU使用率过高的排查步骤。

1、检查CPU高使用率进程

在Linux操作系统下，最常用top命令来监视进程和整体性能，这里可直接通过top -c命令快速定位CPU使用率最高的进程ID：

在这里插入图片描述

我们发现进程ID（PID）为4778的Java程序CPU使用率过高了，达到了93.4%，很明显存在问题

2、导出线程堆栈信息

之后需要借助工具输出该Java程序的线程堆栈信息，后续通过线程的堆栈信息定位具体产生问题的代码。这里比较常用Jstack命令转储堆栈信息。

Jstack命令用于生成虚拟机当前时刻的线程快照，是JDK自带的Java堆栈跟踪工具，用法比较简单：

jstack [进程ID] > 文件名.tdump

另外，通过VisualVM监控工具也可以快速导出线程堆栈信息：

在这里插入图片描述

3、深入识别高使用率线程

接着我们继续使用top命令，深入识别CPU使用率高的进程中具体哪个线程的使用率最高，使用命令如下：

top -Hp [进程ID]

输入top -Hp 4778，详细查看该Java程序中每个线程的CPU使用率，发现PID为4811的使用率最高：

在这里插入图片描述

这里识别到CPU使用率高的线程PID（十进制）后，需要将其转为十六进制，可以借助科学计算器帮我们转换一下，转化后的结果为12cb：

在这里插入图片描述

4、高使用率线程信息定位

最后，我们打开刚才导出tdump线程堆栈信息，搜索十六进制的线程PID，找到对应线程，进一步定位到消耗大量CPU资源的线程源码信息：

在这里插入图片描述

转储出来的线程信息，主要包含这几部分内容：

线程名称：http-nio-8080-exec-2
优先级：prio=5 os_prio=0
Java ID：tid=0x0000000018bfc800
操作系统ID：nid=0x12cb
线程状态：runnable
方法栈：图中详细的方法调用过程

追踪到具体问题是由于处理PerformController对象的handleMessage方法导致的，具体在第14行。

检查源码，发现其实是由于在这里使用while写了死循环，大量消耗了CPU资源：

@RestController
@RequestMapping("/perform")
public class PerformController {

    @GetMapping("/handleMessage")
    public void handleMessage() {
        System.out.println("handleMessage----");
        while (true) {
            // 模拟处理消息
        }
    }

}

在Linux下很容易使用top命令获取CPU使用高的线程，但windows没有直接提供这类命令，只能查看进程的CPU使用率，查看具体线程的CPU使用率则需要额外下载第三方监控工具，可以使用微软的Process Explorer工具或本篇后文介绍的Arthas工具

四、诊断服务响应时间过长

线上服务响应时间过长问题种类一般比较多，既有可能是内存不够导致频繁Full GC，亦或者存在慢查询，资源等待等各种情况。

1、诊断GC及内存问题

关于GC导致的问题以及内存泄漏我们在之前已经详细讲解过，大家可翻阅之前的文章：

【深入JVM：全面解析GC调优】
【深入JVM：线上内存泄漏问题诊断与处理】

抛开此类问题，响应时间过长更多的是因为接口的慢查询或资源等待

2、诊断慢查询

如果确定是某个接口导致的响应时间长，但如果该接口的调用链路特别长，不方便具体跟踪定位是哪个方法执行慢，我们可以使用Arthas工具分析诊断问题。

慢查询通常是数据库慢SQL或数据库死锁

2.1 Arthas线上诊断工具

Arthas是阿里开发的一款线上诊断利器，借用官网原话：Arthas是一款线上监控诊断产品，通过全局视角实时查看应用load、内存、GC、线程的状态信息，并能在不修改应用代码的情况下，对业务问题进行诊断，包括查看方法调用的出入参、异常，监测方法执行耗时，类加载信息等，大大提升线上问题排查效率。

Arthas用法也比较简单，由于其同样是采用Java语言编写的，我们只需要下载Arthas对应的jar包，放在部署程序的服务器上通过java -jar的方式启动即可。

具体用法：

下载Arthas对应jar包：【官方下载地址在这】
启动jar包：
```
java -jar arthas-boot.jar
```
选择需监控的Java程序：输入对应程序的数字编号，再敲回车键

在这里插入图片描述

① trace命令：调用追踪

本次我们追踪接口的响应耗时，只需要用到其中的trace命令，trace 命令能主动搜索 class-pattern／method-pattern 对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

命令基本用法：

trace [全限定类名] [方法名] '#cost > 毫秒值'

参数说明（完整用法在这）：

参数名称	参数说明
class-pattern	类名表达式匹配
method-pattern	方法名表达式匹配
condition-express	条件表达式
[E]	开启正则表达式匹配，默认为通配符匹配
`[n:]`	命令执行次数
`#cost`	方法执行耗时
`[m <arg>]`	指定 Class 最大匹配数量，默认值为 50。长格式为`[maxMatch <arg>]`。

这里我们模拟一个接口updateUserInfo，接口调用过程中使用Thread.sleep(1000)让线程睡眠1秒钟：

@RestController
@RequestMapping("/perform")
public class PerformController {

    @GetMapping("watchMethod")
    public void updateUserInfo(@RequestBody UserInfo user) {
        // 更新数据库表
        updateTable(user);
        // 添加日志记录
        addLog();
    }

    private boolean updateTable(UserInfo user) {
        try {
            // 更新用户信息
            Thread.sleep(1000);
        } catch (Exception e) {
            e.printStackTrace();
        }
        return true;
    }

    private void addLog() {
        // 打印日志
    }
    
}

现明确com.example.demo.controller包下PerformController类的updateUserInfo接口响应时间过长，需要追踪定位其问题，则可以使用如下命令：

trace com.example.demo.controller.PerformController updateUserInfo

若该接口后续再次被调用，则Arthas将会输出其方法的调用链路与耗时：

在这里插入图片描述

另外，我们可以在trace命令中添加'#cost > 毫秒值'参数，过滤出耗时较长的方法，例如：

trace [全限定类名] [方法名] '#cost > 1000'

在指定过滤的毫秒值之后，Arthas仅显示耗时超过1000毫秒的方法调用。

② watch命令：监控方法

在定位到某一耗时过长的方法后，可以使用watch命令详细监控该方法的情况，包括其返回值、抛出异常、入参（完整用法在这）。

命令基本用法：

watch [全限定类名] [方法名] '{params, returnObj}'

参数说明（完整用法在这）：

参数名称	参数说明
class-pattern	类名表达式匹配
method-pattern	函数名表达式匹配
express	观察表达式，默认值：`{params, target, returnObj}`
condition-express	条件表达式
[b]	在函数调用之前观察
[e]	在函数异常之后观察
[s]	在函数返回之后观察
[f]	在函数结束之后(正常返回和异常返回)观察
[E]	开启正则表达式匹配，默认为通配符匹配
[x:]	指定输出结果的属性遍历深度，默认为 1，最大值是 4
`[m <arg>]`	指定 Class 最大匹配数量，默认值为 50。长格式为`[maxMatch <arg>]`。

其中'{params, returnObj}'代表详细打印该方法的入参和出参。

上面我们已经通过trace追踪到具体是updateTable方法耗时较长，这里继续通过watch命令监控该方法的出入参：

watch com.example.demo.controller.PerformController updateTable '{params, returnObj}'

在这里插入图片描述

默认watch命令仅打印输出结果的第一层，而一般出入参基本都是对象，若我们需要详细看到其中的属性值，可以使用-x [n]参数，指定输出结果的属性遍历深度，最大值为4：

在这里插入图片描述

如图，我们看到这里出入参的里面具体的数值也打印出来了。

最后在诊断完问题之后，使用stop命令关闭Arthas服务端，重置所有做过的增强类。

③ thread命令：监控线程

另外Arthas也能帮助我们快速监控当前程序中的所有线程，查看各个线程的CPU使用率以及线程的堆栈信息。

命令基本用法：

thread

参数说明（完整用法在这）：

参数名称	参数说明
id	线程 id
[n:]	指定最忙的前 N 个线程并打印堆栈
[b]	找出当前阻塞其他线程的线程
[i `<value>`]	指定 cpu 使用率统计的采样间隔，单位为毫秒，默认值为 200
[–all]	显示所有匹配的线程

我们继续沿用诊断CPU使用率过高中的代码例子，通过while写死循环，这次使用thread命令去定位：

在这里插入图片描述

Arthas展示出所有线程的基本信息，我们发现其中ID为34的线程CPU使用率过高，接着再次通过thread [线程id]查看该线程的详细信息：

在这里插入图片描述

最终也定位到了造成CPU使用率过高的代码行数。

五、诊断服务运行线程耗尽

服务运行线程耗尽是由于线程由于某种原因导致线程状态不正常，存阻塞性的操作或锁使用不当，造成线程死锁等，线程逐渐被耗尽，新的请求无法被正常处理。

诊断此类问题，基本都是通过线程堆栈信息去定位，基本思路与上面讲解的诊断CPU使用率过高的步骤类似，首先通过Jstack或VisualVM工具导出线程堆栈信息tdump文件，然后具体去分析其中的线程状态，在tdump文件中常见的线程状态有以下五种：

RUNNABLE（可运行状态）：线程正在执行，或者等待CPU资源执行
BLOCKED（阻塞状态）：线程正在等待获取锁，而其他线程已经持有了该锁
WAITING（等待状态）：线程正在等待另一个线程发出特定信号，直到其它线程通知它继续执行
TIMED_WAITING（超时等待状态）：线程正在等待一段时间，直到超时或者其它线程通知它继续执行
TERMINATED（终止状态）：线程已经执行完毕或者因为异常等原因被终止

1、诊断线程死锁

线上服务线程死锁还是比较容易定位的，直接在导出的tdump文件中搜索关键字deadlock即可。

这里模拟一个死锁代码：

@RestController
@RequestMapping("/perform")
public class PerformController {

    private Object lock1 = new Object();
    private Object lock2 = new Object();

    @GetMapping("/deadLock1")
    public void deadLock1() {
        // 获取锁lock1
        synchronized (lock1) {
            // 睡眠2秒
            try {
                Thread.sleep(2000);
                // 尝试获取锁lock2
                synchronized (lock2) {
                    System.out.println("接口deadLock1获取到锁lock2");
                }
            } catch (Exception e) {
                e.printStackTrace();
            }
        }
    }

    @GetMapping("/deadLock2")
    public void deadLock2() {
        // 获取锁lock2
        synchronized (lock2) {
            // 尝试获取锁lock1
            synchronized (lock1) {
                System.out.println("接口deadLock2获取到锁lock1");
            }
        }
    }

}

线程堆栈信息tdump文件中能够显示出死锁标识及锁之间的引用关系，同时详细打印出了产生死锁的代码位置：

在这里插入图片描述

2、线程超时等待及线程阻塞

有时我们也会遇到某个线程显示一直在运行，但是无法处理任务，或者在并发量大的情况下，工作中线程池被占满的情况。

同样，这里我们也模拟一个线程占用的情况：

@Component
public class ScheduleTask {

    @Autowired
    private RestTemplate restTemplate;

    // 使用定时器模拟每半分钟请求一次外部接口，完成数据处理
    @Scheduled(cron = "0/30 * * * * ?")
    public void testScheduleTask() throws Exception {

        String url = "http://127.0.0.1:8080/perform/timeOut";
        // 发起请求
        ResponseEntity<String> result = restTemplate.getForEntity(url, String.class);
        // 数据处理
        System.out.println(result.getBody());
    }
}

上面的代码我们使用SpringBoot自带的@Scheduled定时器，每半分钟请求一次其它外界服务的接口，获取响应后处理响应结果。

但定时任务运行一段时间后，发现不执行了，无法再处理数据。

老样子，第一步导出的线程堆栈信息tdump文件，第二步找到Scheduled定时器的线程：

在这里插入图片描述

这里我们发现这个定时器线程竟然一直处于RUNNABLE运行状态，而不是BLOCKED阻塞或WAITING等待状态，同时日志显示其卡在代码第21行，详细定位到代码：

// 第21行：发起请求
ResponseEntity<String> result = restTemplate.getForEntity(url, String.class);

第21行对应着restTemplate发起http请求，那我们应该能够反应过来，可能是http请求超时了，对方的服务一直不响应，导致我们的服务被阻塞住了。

在这我们只需要配置restTemplate的超时时间即可：

@Configuration
public class RestTemplateConfig {

    @Bean
    public RestTemplate restTemplate() {
        SimpleClientHttpRequestFactory requestFactory = new SimpleClientHttpRequestFactory();
        // 连接超时时间
        requestFactory.setConnectTimeout(1000 * 5);
        // 读取超时时间
        requestFactory.setReadTimeout(1000 * 5);
        return new RestTemplate(requestFactory);
    }
}

另外，我们通常认为在BLOCKED状态下线程才处于阻塞状态，但其实对于我们来说，只要任务没有正常执行了，我们就认为该线程阻塞了。而且更多情况下，我们的线程通常由线程池去管理，如果大量的线程被阻塞，也会导致整个服务的不可用。

六、后记

本文从常见的线上性能问题开始介绍，通过案例演示，逐步带大家分析并诊断CPU使用率过高、接口响应耗时过长以及线程资源耗尽等性能问题，定位过程中演示到的Arthas监控工具其实很强大，小豪只简单介绍了其中的trace、watch和thread命令，其它详细的用法大家可自行查阅官网文档。

线上服务性能问题排查作为Java程序员的必备技能，更多的需要真正实际经历过才能切实掌握，熟练使用相关的监控分析工具，能帮助我们更高效的定位问题，总结一下这几篇提到的工具：有GC调优相关监控GC信息的Jstat和VisualVM，也有分析GC日志的GCViewer和GCeasy，有定位内存泄漏的堆内存分析工具MAT，也有功能更为强大的线上监控诊断工具Arthas，当然大部分在线监控工具都是通过Java Agent（探针）技术实现的。

如果大家觉得内容有价值，不妨考虑点点赞，关注关注小豪，后续小豪将会继续更新其它Java相关文章，大家共同进步~