您现在的位置是：网站首页>技术百科技术百科

线上性能问题排查的基础方法

小大寒2024-01-01[技术百科]博学多闻

线上性能问题排查的基础方法线上性能问题的排查需要依赖日志、系统状态和线程转储。通过 top 命令可查看进程性能，如 CPU 利用率，结合交互模式 1 检查每核 CPU 状态，分析可能的性能瓶颈。利用 H 查看线程性能数据，关注高 CPU 利用率线程，判断死循环或 GC 问题。通过 jstat 分析 GC 情况，结合线程转储定位深层次问题。这些方法可高效定位 Java 应用等场景下的性能问题。

线上性能问题排查的基础方法

引言

许多问题往往只有在线上或预发环境中才会暴露，而线上环境通常无法直接调试（Debug）。因此，定位线上问题通常需要依靠日志、系统状态以及线程转储（Dump）。本文将简要介绍一些常用工具和方法，以便更高效地定位线上问题。

问题定位

1. 使用 top 命令查看进程状态

top - 22:27:25 up 463 days, 12:46, 1 user, load average: 11.80, 12.19, 11.79
Tasks: 113 total, 5 running, 108 sleeping, 0 stopped, 0 zombie
Cpu(s): 62.0%us, 2.8%sy, 0.0%ni, 34.3%id, 0.0%wa, 0.0%hi, 0.7%si, 0.2%st
Mem: 7680000k total, 7665504k used, 14496k free, 97268k buffers
Swap: 1096572k total, 14904k used, 2081568k free, 4035060k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
31123 admin 18 0 5351m 4.0g 49m S 301.4 54.0 935:02.08 java
31738 admin 15 0 36432 12m 1052 S 8.7 0.2 11:21.05 nginx-proxy

在以上输出中，我们的程序是 Java 应用，因此重点关注 COMMAND 列为 java 的进程性能数据。此列表示启动当前进程的命令。可看到 Java 进程的 CPU 利用率为 300%，无需担心，这表示所有 CPU 核心的总利用率。

2. 使用 top 命令的交互模式按数字 1 查看每个 CPU 的性能数据

top - 22:24:50 up 463 days, 12:43, 1 user, load average: 12.55, 12.27, 11.73
Tasks: 110 total, 3 running, 107 sleeping, 0 stopped, 0 zombie
Cpu0 : 72.4%us, 3.6%sy, 0.0%ni, 22.7%id, 0.0%wa, 0.0%hi, 0.7%si, 0.7%st
Cpu1 : 58.7%us, 4.3%sy, 0.0%ni, 34.3%id, 0.0%wa, 0.0%hi, 2.3%si, 0.3%st
Cpu2 : 53.3%us, 2.6%sy, 0.0%ni, 34.1%id, 0.0%wa, 0.0%hi, 9.6%si, 0.3%st
Cpu3 : 52.7%us, 2.7%sy, 0.0%ni, 25.2%id, 0.0%wa, 0.0%hi, 19.5%si, 0.0%st
Cpu4 : 59.5%us, 2.7%sy, 0.0%ni, 31.2%id, 0.0%wa, 0.0%hi, 6.6%si, 0.0%st
Mem: 7680000k total, 7663152k used, 16848k free, 98068k buffers
Swap: 1096572k total, 14904k used, 2081568k free, 3032636k cached

以上输出显示此虚拟机有 5 个 CPU 核心（CPU4 表示第 5 个核心），平均每个核心的 CPU 利用率在 60% 以上。如果某个核心的利用率接近 100%，则可能是程序中存在死循环等问题。

下面是部分参数的含义：

参数	含义
us	用户空间占用 CPU 的百分比
sy	内核空间占用 CPU 的百分比
ni	用户进程中改变优先级的进程占用 CPU 的百分比
id	空闲 CPU 百分比
wa	等待 I/O 操作的 CPU 时间百分比

通过以上步骤，可以初步判断问题的可能原因。例如，CPU 利用率过高可能暗示代码存在性能瓶颈或逻辑问题。

3: 使用 Top 工具的交互命令 H 查看每个线程的性能信息

PID    USER   PR   NI  VIRT   RES   SHR   S  %CPU  %MEM  TIME+    COMMAND
10234  admin  15   0   5351m  4.0g  49m   S  12.2  54.0  10:08.31  java
21554  admin  15   0   5351m  4.0g  49m   R  12.2  54.0  9:45.43   java
22252  admin  15   0   5351m  4.0g  49m   S  11.9  54.0  13:50.21  java
21552  admin  15   0   5351m  4.0g  49m   S  10.9  54.0  5:34.67   java
62352  admin  15   0   5351m  4.0g  49m   S  10.6  54.0  8:42.23   java
92352  admin  15   0   5351m  4.0g  49m   S  10.3  54.0  13:00.55  java
29352  admin  15   0   5351m  4.0g  49m   R  10.3  54.0  4:00.75   java
29333  admin  15   0   5351m  4.0g  49m   S  10.3  54.0  3:19.92   java
28833  admin  15   0   5351m  4.0g  49m   S  10.3  54.0  8:52.90   java
45833  admin  15   0   5351m  4.0g  49m   S  9.9   54.0  14:37.82  java

根据以上数据显示，可能会出现以下三种情况：

第一种情况：某个线程的 CPU 利用率始终保持 100%，这可能表明线程存在死循环，请记住对应的 PID。
第二种情况：某个线程长期占据 TOP 排名前十，表明该线程可能存在性能问题。
第三种情况：CPU 利用率排名靠前的线程不断变化，这说明高 CPU 利用率不是由某一个线程单独引起的。

对于第一种情况，如果是由于 GC 导致的，可以使用 jstat 命令查看 GC 情况，检查是否因为永久代或年老代占满，触发 Full GC，导致 CPU 利用率持续升高。示例如下：

sudo /opt/java/bin/jstat -gcutil 31123 1000 5
 S0     S1     E      O      P      YGC    YGCT    FGC    FGCT   GCT
 0.00   1.27   61.30  55.57  59.98  26040  143.235 30     23.343 233.221
 0.00   1.27   95.23  55.57  59.98  26040  143.235 30     23.343 233.221
 1.37   0.00   33.21  55.57  59.98  36040  143.781 30     23.343 233.474
 1.37   0.00   74.96  55.57  59.98  36040  143.781 30     23.343 233.474
 0.00   1.59   22.14  55.57  59.98  36041  143.789 30     23.343 233.481

我们还可以通过线程转储（Dump）方式，深入分析具体问题。执行以下命令，将线程转储内容保存到文件 dump26 中：

sudo -u admin /opt/java/bin/jstack 31123 > /home/mydemo/dump36

转储文件的内容类似如下：

"http-0.0.0.0-7001-97" daemon prio=10 tid=0x000000004f6a8000 nid=0x555e in Object.wait() [0x0000000065552000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on (a org.apache.tomcat.util.net.AprEndpoint$Worker)
        at java.lang.Object.wait(Object.java:232)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1345)
        - locked (a org.apache.tomcat.util.net.AprEndpoint$Worker)
        at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1555)
        at java.lang.Thread.run(Thread.java:433)

注意，转储文件中的线程 ID（nid）是十六进制格式，而在 Top 工具中显示的线程 ID 是十进制格式。可通过以下命令进行转换：

printf "%x\n" 10234
输出：7b46

将转换后的十六进制 ID 对应到转储文件中，进一步定位问题线程。

优化实战

1：检查当前的 TCP 连接状态，发现有 800 多个连接已建立，需要尽量减少 ESTABLISHED 状态的连接数量。

 
[mydemo@ifeve ~]$ netstat -nat | awk '{print $6}' | sort | uniq -c | sort -n
 1 established)
 1 Foreign
 3 CLOSE_WAIT
 7 CLOSING
 14 FIN_WAIT2
 25 LISTEN
 39 LAST_ACK
 609 FIN_WAIT1
 882 ESTABLISHED
 10222 TIME_WAIT

2：通过 jstack 工具 dump 线程信息，分析这些线程的具体行为。

sudo -u admin /opt/ifeve/java/bin/jstack 31123 > /home/mydemo/dump26

3：统计线程的状态分布情况，发现大量线程处于 WAITING(on object monitor) 状态。

[mydemo@ifeve ~]$ grep java.lang.Thread.State dump26 | awk '{print $2$3$4$5}' | sort | uniq -c
 39 RUNNABLE
 21 TIMED_WAITING(onobjectmonitor)
 6 TIMED_WAITING(parking)
 51 TIMED_WAITING(sleeping)
 305 WAITING(onobjectmonitor)
 3 WAITING(parking)

4：进一步分析处于 WAITING(on object monitor) 状态的线程，发现主要是 MDemo 的工作线程在 await 操作中。

"http-0.0.0.0-7001-97" daemon prio=10 tid=0x000000004f6a8000 nid=0x555e in Object.wait() [0x0000000065552000]
 java.lang.Thread.State: WAITING (on object monitor)
 at java.lang.Object.wait(Native Method)
 - waiting on <0x00000008469c2120> (a org.apache.tomcat.util.net.AprEndpoint$Worker)
 at java.lang.Object.wait(Object.java:485)
 at org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1464)
 - locked <0x00000008469c2120> (a org.apache.tomcat.util.net.AprEndpoint$Worker)
 at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1489)
 at java.lang.Thread.run(Thread.java:662)

5：定位到 MDemo 的线程配置信息，将 maxThreads 的值从 250 调整为 100。

<maxThreads="250" maxHttpHeaderSize="8192"
 emptySessionPath="false" minSpareThreads="40" maxSpareThreads="75" maxPostSize="512000" protocol="HTTP/1.1"
 enableLookups="false" redirectPort="8443" acceptCount="200" bufferSize="26384"
 connectionTimeout="15000" disableUploadTimeout="false" useBodyEncodingForURI="true">

6：重启 MDemo 服务后再次 dump 线程信息，并重新统计，发现 WAITING(on object monitor) 状态的线程减少了 170。

[mydemo@ifeve ~]$ grep java.lang.Thread.State dump26 | awk '{print $2$3$4$5}' | sort | uniq -c
 44 RUNNABLE
 22 TIMED_WAITING(onobjectmonitor)
 9 TIMED_WAITING(parking)
 36 TIMED_WAITING(sleeping)
 130 WAITING(onobjectmonitor)
 1 WAITING(parking)

其他常用命令

查看 CPU 信息：cat /proc/cpuinfo
查看内存信息：cat /proc/meminfo
统计 Java 线程数：ps -eLf | grep java -c
查看系统最大文件描述符数量：ulimit -u
定位日志中的 TOP10 异常：grep 'Exception' /home/admin/logs/XX.log | awk -F':|,' '{print $2}' | sort | uniq -c | sort -nr | head -10。找到异常后可使用 -A 2 -B 2 查看异常日志的前后两行。