后端接口性能优化分析-问题发现问题定义

👏作者简介：大家好，我是爱吃芝士的土豆倪，24届校招生Java选手，很高兴认识大家
📕系列专栏：Spring源码、JUC源码
🔥如果感觉博主的文章还不错的话，请👍三连支持👍一下博主哦
🍂博主正在努力完成2023计划中：源码溯源，一探究竟
📝联系方式：nhs19990716，加我进群，大家一起学习，一起进步，一起对抗互联网寒冬👀

文章目录

定位问题
- 1.慢查询日志
- 2.监控
- - 压测监控核心指标
  - - 系统性能指标
    - - 交易响应时间
      - 系统处理能力
      - 错误率
    - 资源指标
    - - CPU
      - Memory
      - 磁盘吞吐量
      - 网络吞吐量
    - 中间件指标
    - 数据库指标
    - 稳定性指标
    - 可扩展性指标
- 3.链路追踪
问题排查
- 1.个别接口响应慢
- - 链路追踪
  - 在链路上打印日志
  - 死锁问题
  - - 定位死锁
    - - jps
      - jconsole
- 2.所有接口响应慢
- - CPU占用过高
  - 内存占用过高
  - 磁盘问题
  - 网络问题
  - 垃圾回收

定位问题

1.慢查询日志

通常情况下，为了定位sql的性能瓶颈，我们需要开启mysql的慢查询日志。把超过指定时间的sql语句，单独记录下来，方面以后分析和定位问题。

开启慢查询日志需要重点关注三个参数：

slow_query_log 慢查询开关
slow_query_log_file 慢查询日志存放的路径
long_query_time 超过多少秒才会记录日志

通过mysql的set命令可以设置：

set global slow_query_log='ON'; 
set global slow_query_log_file='/usr/local/mysql/data/slow.log';
set global long_query_time=2;

设置完之后，如果某条sql的执行时间超过了2秒，会被自动记录到slow.log文件中。

当然也可以直接修改配置文件my.cnf

[mysqld]
slow_query_log = ON
slow_query_log_file = /usr/local/mysql/data/slow.log
long_query_time = 2

但这种方式需要重启mysql服务。

2.监控

可观测性帮助企业在复杂的分布式系统中更加快速的排查、定位问题，已经是分布式系统中必不可少的运维工具。

可观测性从传统监控场景不断延伸，逐渐覆盖 Metrics、Traces、Logs 三个维度并将之相互融合。在性能压测领域中，可观测性更为重要，除了有助于定位性能问题，其中 Metrics 性能指标更直接决定了压测是否通过，系统最终是否可以上线，具体如下：

Metrics - 监控指标

系统性能指标，包括请求成功率、系统吞吐量、响应时长

资源性能指标，衡量系统软硬件资源使用情况，配合系统性能指标，观察系统资源水位

Logs - 日志

施压引擎日志，观察施压引擎是否健康，压测脚本执行是否有报错

采样日志，采样记录API的请求和响应详情，辅助排查压测过程中的一些出错请求的参数是否正常，并通过响应详情，查看完整的错误信息

Traces - 分布式链路追踪

用于性能问题诊断阶段，通过追踪请求在系统中的调用链路，定位报错 API 的报错系统和报错堆栈，快速定位性能问题点。

压测监控核心指标

压测过程中，对系统硬件、中间件、数据库资源的监控也很重要，包括系统性能指标、资源指标、中间件指标、数据库指标、前端指标、稳定性指标、批量处理指标、可扩展性指标、可靠性指标等。

系统性能指标

交易响应时间

定义：响应时间指用户从客户端发起一个请求开始，到客户端接收到从服务器端返回的响应结束，整个过程所耗费的时间。在性能检测中一般以压力发起端至被压测服务器返回处理结果的时间为计量，单位一般为秒或毫秒。平均响应时间指系统稳定运行时间段内，同一交易的平均响应时间。一般而言，交易响应时间均指平均响应时间。

简称：Response Time: RT

参考标准不同行业不同业务可接受的响应时间是不同的

互联网企业：500 毫秒以下，例如淘宝业务 10 毫秒左右
金融企业：1 秒以下为佳，部分复杂业务 3 秒以下
保险企业：3 秒以下为佳
制造业：5 秒以下为佳
时间窗口：即整个压测过程的时间，不同数据量则时间不一样，例如双 11 和 99 大促，数据量级不一样则时间窗口不同。大数据量的情况下，2 小时内可完成压测

系统处理能力

定义：系统处理能力是指系统在利用系统硬件平台和软件平台进行信息处理的能力。系统处理能力通过系统每秒钟能够处理的交易数量来评价，是技术测试活动中重要指标

简称一般情况下，用以下指标来度量：

HPS（Hits Per Second）：每秒点击次数，单位是次/秒
TPS（Transaction per Second）：系统每秒处理交易数，单位是笔/秒。
QPS（Query per Second）：系统每秒处理查询次数，单位是次/秒。对于互联网业务中，如果某些业务有且仅有一个请求连接，那么 TPS=QPS=HPS，一般情况下用 TPS 来衡量整个业务流程，用 QPS 来衡量接口查询次数，用 HPS 来表示对服务器单击请求

标准无论 TPS、QPS、HPS，此指标是衡量系统处理能力非常重要的指标，越大越好，根据经验，一般情况下：

金融行业：1000 TPS~50000 TPS，不包括互联网化的活动
保险行业：100 TPS~100000 TPS，不包括互联网化的活动
制造行业：10 TPS~5000 TPS
互联网电子商务：10000 TPS~1000000 TPS
互联网中型网站：1000 TPS~50000 TPS
互联网小型网站：500 TPS~10000 TPS

错误率

定义：错误率指系统在负载情况下，失败交易的概率。错误率＝（失败交易数/交易总数）×100%。稳定性较好的系统，其错误率应该由超时引起，即为超时率。

标准不同系统对错误率的要求不同，但一般不超出千分之六，即成功率不低于 99.4%

资源指标

CPU

定义：中央处理器是一块超大规模的集成电路，是一台计算机的运算核心（Core）和控制核心（ Control Unit）。它的功能主要是解释计算机指令以及处理计算机软件中的数据。

Memory

定义内存是计算机中重要的部件之一，它是与 CPU 进行沟通的桥梁。计算机中所有程序的运行都是在内存中进行的，因此内存的性能对计算机的影响非常大

磁盘吞吐量

定义磁盘吞吐量是指在无磁盘故障的情况下单位时间内通过磁盘的数据量

网络吞吐量

定义网络吞吐量是指在无网络故障的情况下单位时间内通过的网络的数据数量。单位为 Byte/s。网络吞吐量指标用于衡量系统对于网络设备或链路传输能力的需求。当网络吞吐量指标接近网络设备或链路最大传输能力时，则需要考虑升级网络设备

中间件指标

在这里插入图片描述

数据库指标

在这里插入图片描述

数据库监控中的命中率通常指的是缓存命中率，它表示在数据库访问中，请求能够从缓存中获取所需数据的比例。换句话说，命中率越高，就意味着数据库查询所需的数据越多地可以从缓存中获取，而不需要去访问磁盘或进行其他昂贵的操作。这通常被认为是一个性能指标，因为高命中率通常意味着更快的响应时间和更好的系统性能。

稳定性指标

定义：最短稳定时间：系统按照最大容量的 80% 或标准压力（系统的预期日常压力）情况下运行，能够稳定运行的最短时间。一般来说，对于正常工作日（8小时）运行的系统，至少应该能保证系统稳定运行８小时以上。对于 7×24 运行的系统，至少应该能够保证系统稳定运行 24 小时以上。如果系统不能稳定的运行，上线后，随着业务量的增长和长时间运行，将会出现性能下降甚至崩溃的风险

标准

TPS 曲线稳定，没有大幅度的波动
各项资源指标没有泄露或异常情况

可扩展性指标

定义：指应用软件或操作系统以集群方式部署，增加的硬件资源与增加的处理能力之间的关系。计算公式为：（增加性能/原始性能）/（增加资源/原始资源）×100%。扩展能力应通过多轮测试获得扩展指标的变化趋势。一般扩展能力非常好的应用系统，扩展指标应是线性或接近线性的，现在很多大规模的分布式系统的扩展能力非常好。

标准

理想的扩展能力是资源增加几倍，性能就提升几倍。
扩展能力至少在70%以上。

目前业界使用比较多的开源监控系统是：Prometheus。

它提供了 监控 和 预警 的功能。

我们可以用它监控如下信息：

接口响应时间
调用第三方服务耗时
慢查询sql耗时
cpu使用情况
内存使用情况
磁盘使用情况
数据库使用情况

它的界面大概长这样子：

在这里插入图片描述

可以看到mysql当前qps，活跃线程数，连接数，缓存池的大小等信息。

如果发现数据量连接池占用太多，对接口的性能肯定会有影响。

这时可能是代码中开启了连接忘了关，或者并发量太大了导致的，需要做进一步排查和系统优化。

3.链路追踪

有时候某个接口涉及的逻辑很多，比如：查数据库、查redis、远程调用接口，发mq消息，执行业务代码等等。

该接口一次请求的链路很长，如果逐一排查，需要花费大量的时间，这时候，我们已经没法用传统的办法定位问题了。

有没有办法解决这问题呢？

用分布式链路跟踪系统：skywalking。

通过skywalking定位性能问题：

在这里插入图片描述

在skywalking中可以通过traceId（全局唯一的id），串联一个接口请求的完整链路。可以看到整个接口的耗时，调用的远程服务的耗时，访问数据库或者redis的耗时等等，功能非常强大。

之前没有这个功能的时候，为了定位线上接口性能问题，我们还需要在代码中加日志，手动打印出链路中各个环节的耗时情况，然后再逐一排查。

问题排查

1.个别接口响应慢

链路追踪

使用SkyWalking，展示出每一个与网络有关的耗时。比如：读写数据库、读写Redis、SpringCloud调用、Dubbo调用等。这样就能立马定位是哪次操作耗时了。

同时，SkyWalking可以记录每一个SQL语句，可以帮助定位。

例如：（如箭头所指处，最上边一个是总耗时，下边的线段是单个操作的耗时）

在这里插入图片描述

在链路上打印日志

在相应的链路上打印日志，然后查看日志，看是哪个地方耗时。

死锁问题

在这里重点讲一下出现死锁问题的排查经验吧

有这样的情况：一个线程需要同时获取多把锁，这时就容易发生死锁

t1 线程获得 A对象锁，接下来想获取 B对象的锁 t2 线程获得 B对象锁，接下来想获取 A对象的锁

Object A = new Object();
    Object B = new Object();
    Thread t1 = new Thread(() -> {
        synchronized (A) {
            log.debug("lock A");
            sleep(1);
            synchronized (B) {
                log.debug("lock B");
                log.debug("操作...");
            }
        }
    }, "t1");
    Thread t2 = new Thread(() -> {
        synchronized (B) {
            log.debug("lock B");
            sleep(0.5);
            synchronized (A) {
                log.debug("lock A");
                log.debug("操作...");
            }
        }
    }, "t2");
    t1.start();
    t2.start();

12:22:06.962 [t2] c.TestDeadLock - lock B 
12:22:06.962 [t1] c.TestDeadLock - lock A

定位死锁

检测死锁可以使用 jconsole工具，或者使用 jps 定位进程 id，再用 jstack 定位死锁：

jps

cmd > jps
Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF-8
12320 Jps
22816 KotlinCompileDaemon
33200 TestDeadLock // JVM 进程
11508 Main
28468 Launcher

cmd > jstack 33200
        Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF-8
        2018-12-29 05:51:40
        Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.91-b14 mixed mode):
        "DestroyJavaVM" #13 prio=5 os_prio=0 tid=0x0000000003525000 nid=0x2f60 waiting on condition
        [0x0000000000000000]
        java.lang.Thread.State: RUNNABLE
        "Thread-1" #12 prio=5 os_prio=0 tid=0x000000001eb69000 nid=0xd40 waiting for monitor entry
        [0x000000001f54f000]
        java.lang.Thread.State: BLOCKED (on object monitor)
        at thread.TestDeadLock.lambda$main$1(TestDeadLock.java:28)
        - waiting to lock <0x000000076b5bf1c0> (a java.lang.Object)
        - locked <0x000000076b5bf1d0> (a java.lang.Object)
        at thread.TestDeadLock$$Lambda$2/883049899.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:745)
        "Thread-0" #11 prio=5 os_prio=0 tid=0x000000001eb68800 nid=0x1b28 waiting for monitor entry
        [0x000000001f44f000]
        java.lang.Thread.State: BLOCKED (on object monitor)
        at thread.TestDeadLock.lambda$main$0(TestDeadLock.java:15)
        - waiting to lock <0x000000076b5bf1d0> (a java.lang.Object)
        - locked <0x000000076b5bf1c0> (a java.lang.Object)
        at thread.TestDeadLock$$Lambda$1/495053715.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:745)

// 略去部分输出
        Found one Java-level deadlock:
        =============================
        "Thread-1":
        waiting to lock monitor 0x000000000361d378 (object 0x000000076b5bf1c0, a java.lang.Object),
        which is held by "Thread-0"
        "Thread-0":
        waiting to lock monitor 0x000000000361e768 (object 0x000000076b5bf1d0, a java.lang.Object),
        which is held by "Thread-1"
        Java stack information for the threads listed above:
        ===================================================
        "Thread-1":
        at thread.TestDeadLock.lambda$main$1(TestDeadLock.java:28)
        - waiting to lock <0x000000076b5bf1c0> (a java.lang.Object)
        - locked <0x000000076b5bf1d0> (a java.lang.Object)
        at thread.TestDeadLock$$Lambda$2/883049899.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:745)
        "Thread-0":
        at thread.TestDeadLock.lambda$main$0(TestDeadLock.java:15)
        - waiting to lock <0x000000076b5bf1d0> (a java.lang.Object)
        - locked <0x000000076b5bf1c0> (a java.lang.Object)
        at thread.TestDeadLock$$Lambda$1/495053715.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:745)
        Found 1 deadlock

这里是两个线程 “Thread-0” 和 “Thread-1” 在互相等待对方释放锁，从而导致了死锁。

线程 “Thread-1” 试图获取对象0x000000076b5bf1c0的监视器锁（即synchronized关键字保护的那个对象），但是这个锁已经被线程 “Thread-0” 持有。因此，“Thread-1” 进入了等待状态，等待 “Thread-0” 释放这个锁。

同时，线程 “Thread-0” 试图获取对象0x000000076b5bf1d0的监视器锁，但是这个锁已经被线程 “Thread-1” 持有。因此，“Thread-0” 进入了等待状态，等待 “Thread-1” 释放这个锁。

jconsole

在这里插入图片描述

2.所有接口响应慢

如果线上出了问题，首先判断是业务问题还是整个系统的问题。如果是业务问题，就去看应用的日志等进行排查。如果出现了如下问题，就可能是整个系统的问题

大量接口都很慢
页面打不开

如何得知系统出问题了？

系统出问题时，我们需要进行详细排查，一般情况下，有以下场景我们可以得知线上出问题了：

用户反馈功能不能正常使用
监控系统的邮件或者短信提醒

系统问题排查步骤

以下按顺序进行

是否CPU占用过高
是否内存占用过高
是否磁盘占用过高
是否网络故障
查看后台日志
是否是数据库问题（比如：索引失效、死锁）
是否是垃圾回收导致

CPU占用过高

什么场景需要排查CPU占用？

访问接口的响应速度很慢。
系统崩溃无响应
压测时要查看CPU、内存、load、rt、qps等指标

步骤简述

定位进程（命令：top）
定位线程（命令：top -Hp 进程号）
定位代码位置（命令：jstack）

排查方法详述

找到占CPU最高的进程。
1. top命令，记下进程号（PID）。假设最高的是：1893
通过进程找到对应的线程。
1. top -Hp 1893。假设最高的是：4519
2. （因为Java是单进程多线程的）
通过线程定位到代码大概的位置信息。
1. printf %x 4519。结果为：11a7
2. jstack 1893 | grep 11a7 -A 30 –color
  结果大概是这样的：

在这里插入图片描述

可能导致CPU使用率飙升的操作

无限循环的while
经常使用Young GC
频繁的GC

如果访问量很高，可能会导致频繁的GC甚至Full GC。当调用量很大时，内存分配将如此之快以至于GC线程将连续执行，这将导致CPU飙升。

序列化和反序列化

序列化和反序列化本身不会导致CPU使用率飙升。序列化是将对象转换为字节流的过程，而反序列化则是将字节流转换回对象的过程。这两个过程通常在内存中完成，并不直接导致CPU使用率的飙升。

然而，在某些情况下，序列化和反序列化可能会导致CPU使用率增加。例如，当需要大量的数据进行序列化或反序列化时，可能会消耗较多的CPU资源。此外，如果序列化和反序列化的操作频繁且耗时较长，也可能对CPU使用率产生一定影响。

正则表达式

正则表达式本身不会导致CPU飙升，但是使用不当或者复杂的正则表达式可能会导致CPU负载增加。

正则表达式在处理大量文本时，特别是复杂的表达式或者需要进行大量回溯的情况下，可能会消耗大量的 CPU 资源。这是因为正则表达式引擎需要在文本中进行搜索和匹配，并且有些复杂的规则可能需要大量的计算才能找到匹配的结果。

因此，在编写正则表达式时，需要注意避免过于复杂或低效的表达式，尤其是在处理大量文本的场景下。另外，对于一些需要频繁执行的操作，可以考虑在代码中进行优化，以减少对 CPU 的负载影响。

线程上下文切换

内存占用过高

步骤简述

定位Java程序内存使用过高或者内存泄漏的问题跟CPU也类似，可分为以下步骤：

定位进程（命令：top）
定位线程（命令：top -Hp 进程号）
定位代码位置（命令：jmap生成快照，MAT / jprofiler / VisualVM / jhat 查看快照数据）

1.定位进程

top
按下M（按内存占用由大到小排序）
1. // 假设定位到的进程ID为14279。

2.定位线程

top -Hp 14279;

按下M（按内存占用由大到小排序）

top - 18:33:07 up 25 days,  7:48,  1 user,  load average: 0.17, 0.27, 0.23
Threads:  54 total,   1 running,  53 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.5 us,  0.7 sy,  0.0 ni, 98.8 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8168236 total,   231696 free,  3660496 used,  4276044 buff/cache
KiB Swap:   969964 total,   969964 free,        0 used.  4197860 avail Mem
  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
14293 weiping   20   0 4508772  97036  18112 S  10    12 152:35.42 java
14279 weiping   20   0 4508772  97036  18112 S  5.0  1.2   0:00.00 java
14282 weiping   20   0 4508772  97036  18112 S  0.0  1.2   0:00.37 java

注意观察两点：

线程的数量
1. 可以看到，它线程数是54（左上角的Threads项），属于正常。
2. 若比较大（比如大于1000），要考虑是不是代码有问题：
  1. 是不是代码里手动起了多个线程。比如：使用OkHttpClient时每次都创建了连接池（ConnectionPool）；应该是只创建一个连接池的。
  2. 是不是自己创建的线程池最大个数太大了。
占内存大的线程的PID
1. 如果线程数量正常，就要dump内存的快照信息来查看。

3.定位代码位置

如果是线上环境，注意dump之前必须先将流量切走，否则大内存dump是直接卡死服务。

dump当前快照：jmap -dump:format=b,file=dump.hprof 14279

查找实例数比较多的业务相关的实例，然后找到相应代码查看。（使用工具查看dump.hprof。比如：MAT、VisualVM、jhat）

磁盘问题

步骤简介

是否磁盘快用完了（命令：df、du）
TPS是否正常（命令：iostat、vmstat、lsof）

这个命令是用来检查系统的磁盘性能是否正常。具体来说：

iostat 命令用于报告 CPU 使用情况和磁盘I/O统计信息。
vmstat 命令用于报告虚拟内存统计信息。
lsof 命令用于列出打开文件。

通过使用这些命令，可以获得关于磁盘 I/O 活动、CPU 使用率、内存使用等方面的统计数据。其中，磁盘 I/O 统计信息中的 TPS（每秒传输的 I/O 操作数）可以用来评估磁盘的性能是否正常。如果 TPS 过高或者过低，可能意味着磁盘存在性能问题，需要进一步分析和解决。

网络问题

垃圾回收

什么情况下，GC会对程序产生影响？

不管Minor GC还是FGC，都会造成一定程度的程序卡顿（即Stop The World：GC线程开始工作，其他工作线程被挂起），即使采用ParNew、CMS或者G1这些更先进的垃圾回收算法，也只是在减少卡顿时间，而并不能完全消除卡顿。

那到底什么情况下，GC会对程序产生影响呢？根据严重程度从高到底，包括以下4种情况：

FGC过于频繁
1. FGC通常比较慢，少则几百毫秒，多则几秒，正常情况FGC每隔几个小时甚至几天才执行一次，对系统的影响还能接受。
2. 一旦出现FGC频繁（比如几十分钟执行一次），是存在问题的，会导致工作线程频繁被停止，让系统看起来一直有卡顿现象，也会使得程序的整体性能变差。
YGC耗时过长
1. 一般来说，YGC的总耗时在几十或者上百毫秒是比较正常的，虽然会引起系统卡顿几毫秒或者几十毫秒，这种情况几乎对用户无感知，对程序的影响可以忽略不计。
2. 如果YGC耗时达到了1秒甚至几秒（都快赶上FGC的耗时了），那卡顿时间就会增大，加上YGC本身比较频繁，就会导致比较多的服务超时问题。
FGC耗时过长
1. FGC耗时增加，卡顿时间也会随之增加，尤其对于高并发服务，可能导致FGC期间比较多的超时问题，可用性降低，这种也需要关注。
YGC过于频繁
1. 即使YGC不会引起服务超时，但是YGC过于频繁也会降低服务的整体性能，对于高并发服务也是需要关注的。

如何排查

公司的监控系统：大部分公司都会有，可全方位监控JVM的各项指标。
JDK自带工具：jmap、jstat
1. 查看堆内存各区域的使用率以及GC情况：jstat -gcutil pid 1000 （重点关注结果中的YGC、YGCT、FGC、FGCT、GCT）
2. 查看堆内存中的存活对象，并按空间排序：jmap -histo pid | head -n20
3. dump堆内存文件：jmap -dump:format=b,file=heap pid