Zhanghao Blog
线上性能问题 - CPU 飙升100%+
2025-05-31
场景与实战
0

目录

Java进程的CPU飙升
问题现象
问题定位与分析
确认 CPU 负载来源 (操作系统层面)
获取 Java 线程快照 (JVM 层面)
分析线程转储
排查思路总结
新玩法：show-busy-java-threads 脚本
安装
用法
MySQL的CPU使用率飙升
问题定位
了解下 show processlist
show processlist 参数分析
问题分析
排查思路总结

线上的CPU飙升是每个系统都绕不开的话题，这是典型的线上性能问题的排查场景，除了CPU飙升，还有 频繁GC、内存打满 等问题，在工作的过程中，我们或多或少的都会接触到此类的一些问题，接下来我结合生产案例来讲述下排查的思路

Java进程的CPU飙升

问题现象

监控系统报警：order-service Java 进程 CPU 使用率持续超过 300%，服务响应时间飙升，部分请求超时失败。

问题定位与分析

确认 CPU 负载来源 (操作系统层面)

首先通过 top 指令查看当前占用CPU较高的进程PID；可以通过以下指令快速查询前5个CPU最高的线程

shell

ps -eo pid,ppid,cmd,%cpu --sort=-%cpu | head -n 5

观察到 java 进程 PID 为 12345 的进程 CPU 占用率稳定在 300%+，远超其他进程。确认是 Java 进程本身的问题，而非系统其他进程或外部因素（如病毒）。

接下来通过 top -Hp [PID] 命令 查看进程内线程,执行 top -Hp 12345 观察到有 3-4 个线程 (nid=0x4a3b, nid=0x4a3c, nid=0x4a3d) 的 CPU 使用率持续在 90%-99% 之间。记录下这些高 CPU 线程的 PID (这里是十六进制的 nid，即 Native Thread ID)。

获取 Java 线程快照 (JVM 层面)

提示

通过 print 命令可以将线程PID转为16进制，根据该16进制值去打印的堆栈日志内查询，查看该线程所驻留的方法位置。

使用jvm内置 jstack 命令抓取线程转储 jstack -l 进程ID

shell

jstack -l 12345 > jstack_12345.log

可以多次抓取（间隔 5-10 秒，抓 3-5 次）：因为线程状态是瞬时的，多次抓取有助于发现持续活跃的线程。将输出保存到文件 jstack_12345_1.log, jstack_12345_2.log 等。

分析线程转储

将 top -Hp 中线程的十进制 PID (Linux 线程 PID) 转换为十六进制。

通过 print 命令可以将线程PID转为16进制，printf "%x\n" 19003 (假设 top -Hp 看到的十进制线程 PID 是 19003) -> 输出 0x4a3b。

根据该16进制值去打印的堆栈日志内查询，在 jstack_12345.log 文件中通过 grep '0x4a3b' jstack_12345.log -A100 搜索这个十六进制值(nid=0x4a3b)来查看该线程所驻留的方法位置。

java

"Order-Processing-Thread-7" #32 daemon prio=5 os_prio=0 tid=0x00007f8ea422e800 nid=0x4a3b runnable [0x00007f8e8a7f1000]
java.lang.Thread.State: RUNNABLE
    at com.example.orderservice.InventoryManager.lockStock(InventoryManager.java:105)
    at com.example.orderservice.InventoryManager.lambda$lockStockForItems$0(InventoryManager.java:87)
    at com.example.orderservice.InventoryManager$$Lambda$45/0x00000008000b2840.apply(Unknown Source)
    at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
    at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655)
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
    at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578)
    at com.example.orderservice.InventoryManager.lockStockForItems(InventoryManager.java:89)
    at com.example.orderservice.OrderService.createOrder(OrderService.java:55)
    ...

直接分析

可以通过 jstack 【进程PID】| grep 【线程转换后十六进制】-A10 直接查询线程的十六进制进行定位分析，利用grep定位线程id，打印后续10行信息。例如：jstack 373 | grep '0x196' -A10

关键观察点

  • 线程状态： RUNNABLE - 表示线程正在执行或等待 CPU 时间片（这正是高 CPU 的特征）。
  • 线程名： "Order-Processing-Thread-7" - 是应用自定义的线程池线程，指向订单处理逻辑。
  • 堆栈顶部： com.example.orderservice.InventoryManager.lockStock(InventoryManager.java:105) 这是线程当前正在执行（或最近执行）的代码位置。这是最直接的线索！

在找到线索的同时，再次检查其他几次 jstack.log 快照的输出中，同一个 nid 的线程是否 持续 停留在 InventoryManager.lockStock 方法附近。如果是，这基本锁定了问题代码区域。

观察其他高 CPU 线程 (nid=0x4a3c, 0x4a3d) 的堆栈。发现它们 几乎完全相同，都卡在 lockStock 方法，只是线程名不同 (Order-Processing-Thread-8, -9 等)。这表明多个线程在执行同一段有问题的代码。

排查思路总结

  • 监控报警确认： CPU 飙升告警 -> 登录服务器确认。
  • 系统层面定位进程： top -> 确认高 CPU 进程是目标 Java 进程 (PID=12345)。
  • 定位进程内高 CPU 线程： top -Hp 12345 -> 记录高 CPU 线程的 十进制 PID -> 转换为 十六进制 nid (printf "%x")。
  • 获取线程快照： jstack -l 12345 > jstack.log (务必多次抓取！)。
  • 关联分析线程： 在 jstack.log 中搜索 nid=0x... (上一步转换的十六进制值) -> 找到对应的 Java 线程堆栈。
  • 聚焦问题堆栈
  1. 检查 线程状态 (RUNNABLE 是重点)。
  2. 查看 线程名 (自定义线程名能快速定位业务模块)。
  3. 精读堆栈顶部 (当前执行点) 的方法和行号。
  4. 对比多次快照，看高 CPU 线程是否持续停留在相同代码位置。
  • 结合代码分析： 根据堆栈顶部的类名、方法名、行号 (InventoryManager.java:105)，查看对应源代码，理解逻辑，分析为何会消耗大量 CPU (死循环？ 密集计算？ 锁竞争自旋？ 资源争用？)。
  • 根因定位与解决： 根据代码分析结果，确定是算法问题、死循环、锁设计缺陷还是其他资源瓶颈，制定并实施解决方案（优化算法、修复死循环、重构锁策略、扩容资源等）。
  • 验证与预防
  1. 修复后，在预发布/压测环境模拟场景验证。
  2. 添加针对性的监控（如特定方法的执行时间、特定锁的等待时间）。
  3. 加强代码审查，特别是并发和循环逻辑。
  4. 进行定期的压力测试。

新玩法：show-busy-java-threads 脚本

以上是我们传统的玩法，总结一下就是:

top命令找出消耗CPU高的Java进程及其线程id：

  • 开启线程的显示模式（top -H，或者打开top后按H）。
  • 按cpu使用率排序（top缺省就是按CPU的使用率降序）。
  • 记下Java进程id及其CPU高的线程id。

查看消耗CPU高的线程栈：

  • 用进程id作为参数，jstack出有问题的Java进程。
  • 手动转换线程id成16进制（可以使用 printf %x pid）。
  • 在jstack输出中查找16进制的线程id（jstack -l pid > test.txt | grep16进制的值）

查看对应的线程栈，分析问题。查问题时，会要多次上面的操作以分析确定问题，这个过程太繁琐太慢了。现在我们来认识一下阿里的一个工具脚本 show-busy-java-threads

安装

从官方文档上可以看到有3种安装方式，此处推荐使用直接在网络上下载脚本

sh

# 下载脚本
wget --no-check-certificate https://raw.github.com/oldratlee/useful-scripts/release/show-busy-java-threads

# 运行脚本
sh ./show-busy-java-threads

用法

基本命令

sh

# 从所有运行的Java进程中找出最消耗CPU的线程（缺省5个），打印出其线程栈
show-busy-java-threads

# 缺省会自动从所有的Java进程中找出最消耗CPU的线程，这样用更方便
# 当然你可以手动指定要分析的Java进程Id，以保证只会显示你关心的那个Java进程的信息
show-busy-java-threads -p <指定的Java进程Id>

show-busy-java-threads -c <要显示的线程栈数>

# 多次执行
show-busy-java-threads <重复执行的间隔秒数> [<重复执行的次数>]

# 记录到文件以方便回溯查看
show-busy-java-threads -a <运行输出的记录到的文件>

# 指定jstack输出文件的存储目录，方便记录以后续分析
show-busy-java-threads -S <存储jstack输出文件的目录>

注意事项

sh

# 如果Java进程的用户 与 执行脚本的当前用户 不同，则jstack不了这个Java进程
# 为了能切换到Java进程的用户，需要加sudo来执行，即可以解决：
sudo show-busy-java-threads

# 对于sudo方式的运行，JAVA_HOME环境变量不能传递给root，
# 而root用户往往没有配置JAVA_HOME且不方便配置，
# 显式指定jstack命令的路径就反而显得更方便了
show-busy-java-threads -s <指定jstack命令的全路径>
2.2.3 其他命令

# -m选项：执行jstack命令时加上-m选项，显示上Native的栈帧，一般应用排查不需要使用
show-busy-java-threads -m
# -F选项：执行jstack命令时加上 -F 选项（如果直接jstack无响应时，用于强制jstack），一般情况不需要使用
show-busy-java-threads -F
# -l选项：执行jstack命令时加上 -l 选项，显示上更多相关锁的信息，一般情况不需要使用
# 注意：和 -m -F 选项一起使用时，可能会大大增加jstack操作的耗时
show-busy-java-threads -l

示例

sh

$ show-busy-java-threads
[1] Busy(57.0%) thread(23355/0x5b3b) stack of java process(23269) under user(admin):
"pool-1-thread-1" prio=10 tid=0x000000005b5c5000 nid=0x5b3b runnable [0x000000004062c000]
   java.lang.Thread.State: RUNNABLE
    at java.text.DateFormat.format(DateFormat.java:316)
    at com.xxx.foo.services.common.DateFormatUtil.format(DateFormatUtil.java:41)
    at com.xxx.foo.shared.monitor.schedule.AppMonitorDataAvgScheduler.run(AppMonitorDataAvgScheduler.java:127)
    at com.xxx.foo.services.common.utils.AliTimer$2.run(AliTimer.java:128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)

[2] Busy(26.1%) thread(24018/0x5dd2) stack of java process(23269) under user(admin):
"pool-1-thread-2" prio=10 tid=0x000000005a968800 nid=0x5dd2 runnable [0x00000000420e9000]
   java.lang.Thread.State: RUNNABLE
    at java.util.Arrays.copyOf(Arrays.java:2882)
    at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100)
    at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:572)
    at java.lang.StringBuffer.append(StringBuffer.java:320)
    - locked <0x00000007908d0030> (a java.lang.StringBuffer)
    at java.text.SimpleDateFormat.format(SimpleDateFormat.java:890)
    at java.text.SimpleDateFormat.format(SimpleDateFormat.java:869)
    at java.text.DateFormat.format(DateFormat.java:316)
    at com.xxx.foo.services.common.DateFormatUtil.format(DateFormatUtil.java:41)
    at com.xxx.foo.shared.monitor.schedule.AppMonitorDataAvgScheduler.run(AppMonitorDataAvgScheduler.java:126)
    at com.xxx.foo.services.common.utils.AliTimer$2.run(AliTimer.java:128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)

......

上面的线程栈可以看出，CPU 消耗最高的 2 个线程都在执行 java.text.DateFormat.format，业务代码对应的方法是 shared.monitor.schedule.AppMonitorDataAvgScheduler.run。可以基本确定：

  • AppMonitorDataAvgScheduler.run 调用 DateFormat.format 次数比较频繁。
  • DateFormat.format 比较慢。（这个可以由 DateFormat.format 的实现确定。）

多执行几次 show-busy-java-threads，如果上面情况高概率出现，则可以确定上面的判定。因为调用越少代码执行越快，则出现在线程栈的概率就越低。脚本有自动多次执行的功能，可以指定 重复执行的间隔秒数/重复执行的次数 参数。

分析 shared.monitor.schedule.AppMonitorDataAvgScheduler.run 实现逻辑和调用方式，以优化实现解决问题。

MySQL的CPU使用率飙升

首先，我们要对问题定位而不是盲目的开启什么慢日志，在并发量大并且大量SQL性能低的情况下，开启慢日志无意是将MySQL推向崩溃的边缘。

问题定位

当时遇到这个情况，分析了当前的数据量、索引情况、缓存使用情况。目测数据量不大，也就几百万条而已。接下来就去定位索引、缓存问题。

经过询问，发现很多查询都是走MySQL，没有用到缓存。既然没有用到缓存，则是大量请求全部查询MySQL导致，可以通过下面的命令查看:

sql

show processlist;

以此来找出哪些查询可能是瓶颈，并据此进行优化。

了解下 show processlist

通常我们通过 Top 检查发现 mysql CPU 或者 io wait 过高 那么解决这些问题都离不开 show processlist。show processlist 是显示用户正在运行的线程，需要注意的是，除了root用户能看到所有正在运行的线程外，其他用户都只能看到自己正在运行的线程，看不到其它用户正在运行的线程。除非单独个这个用户赋予了PROCESS 权限。

注意

show processlist 只显示前100条 我们可以通过 show full processlist 显示全部。

show processlist 显示的信息都是来自MySQL系统库 information_schema 中的 processlist 表。所以使用下面的查询语句可以获得相同的结果：

sql

SELECT * FROM information_schema.processlist;
SELECT * FROM information_schema.processlist WHERE TIME > 5 ORDER BY TIME DESC;

show processlist 参数分析

  • Id：登录mysql后，系统分配的connection_id表示线程的唯一标识，可以使用函数connection_id()查看。当需要kill一个语句的时候会用到。前面我们说了show processlist显示的信息时来自information_schema.processlist表，所以这个Id就是这个表的主键。
  • User：就是指启动这个线程的用户,如果是system user，它是指由服务器产生的非客户线程，以在内部处理任务。
  • Host：记录了发送请求的客户端的IP和端口号。通过这些信息在排查问题的时候，我们可以定位到是哪个客户端的哪个进程发送的请求。
  • db：当前执行的命令是在哪一个数据库上。如果没有指定数据库，则该值为 NULL 。
  • Command：显示当前连接的执行的命令，一般就是休眠或空闲（sleep），查询（query），连接（connect）。这个参数很复杂，有兴趣可以单独去了解
  • Time：表示该线程处于当前状态的时间，单位是秒。
  • State：显示使用当前连接的sql语句的状态，请注意，state只是语句执行中的某一个状态，一个 sql语句，已查询为例，可能需要经过copying to tmp table，Sorting result，Sending data等状态才可以完成
  • Info：一般记录的是线程执行的语句，对于长时间运行的查询，这可以是有用的调试信息。默认只显示前100个字符，也就是你看到的语句可能是截断了的，要看全部信息，需要使用 show full processlist。

问题分析

通过上述发现类似很多相同的SQL语句，一直处于query状态中。select id form user where user_code = 'xxxxx';

初步分析可能是 user_code 字段没有索引导致，接着查询user表的索引情况：show index form user; 发现这个字段是没有建立索引。增加索引之后，该条SQL查询能够正常执行。没隔一会，又发生大量的请求超时问题。

接着进行分析，发现是开启了慢日志查询。大量的SQL查询语句超过慢日志设置的阀值，于是将慢日志关闭之后，速度瞬间提升,但还不是理想状态。

紧接着将部分实时查询数据的SQL语句，都通过缓存(redis)读写实现。观察一段时间后，基本维持在了70%~ 80%。

排查思路总结

其实本次事故的解决很简单，就是添加索引与缓存结合使用。不推荐在这种CPU使用过高的情况下进行慢日志的开启。因为大量的请求，如果真是慢日志问题会发生日志磁盘写入，性能贼低。

直接通过MySQL show processlist 命令查看，基本能清晰的定位出部分查询问题严重的SQL语句，在针对该SQL语句进行分析。一般可能就是索引、锁、查询大量字段、大表等查询问题导致。再则一定要使用缓存系统，降低对MySQL的查询频次。对于内存调优，也是一种解决方案。

本文作者:张豪

本文链接:

版权声明:本博客所有文章除特别声明外，均采用 BY-NC-SA 许可协议。转载请注明出处！