线上的CPU飙升是每个系统都绕不开的话题,这是典型的线上性能问题的排查场景,除了CPU飙升,还有 频繁GC、内存打满 等问题,在工作的过程中,我们或多或少的都会接触到此类的一些问题,接下来我结合生产案例来讲述下排查的思路
监控系统报警:order-service Java 进程 CPU 使用率持续超过 300%,服务响应时间飙升,部分请求超时失败。
首先通过 top
指令查看当前占用CPU较高的进程PID;可以通过以下指令快速查询前5个CPU最高的线程
shellps -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)。
提示
通过 print
命令可以将线程PID转为16进制,根据该16进制值去打印的堆栈日志内查询,查看该线程所驻留的方法位置。
使用jvm内置 jstack 命令抓取线程转储 jstack -l 进程ID
shelljstack -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
关键观察点
在找到线索的同时,再次检查其他几次 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 线程堆栈。
聚焦问题堆栈
- 检查线程 状态 (RUNNABLE 是重点)。
- 查看 线程名 (自定义线程名能快速定位业务模块)。
- 精读堆栈顶部 (当前执行点) 的方法和行号。
- 对比多次快照,看高 CPU 线程是否持续停留在相同代码位置。
结合代码分析: 根据堆栈顶部的类名、方法名、行号 (InventoryManager.java:105),查看对应源代码,理解逻辑,分析为何会消耗大量 CPU (死循环? 密集计算? 锁竞争自旋? 资源争用?)。
根因定位与解决: 根据代码分析结果,确定是算法问题、死循环、锁设计缺陷还是其他资源瓶颈,制定并实施解决方案(优化算法、修复死循环、重构锁策略、扩容资源等)。
验证与预防
- 修复后,在预发布/压测环境模拟场景验证。
- 添加针对性的监控(如特定方法的执行时间、特定锁的等待时间)。
- 加强代码审查,特别是并发和循环逻辑。
- 进行定期的压力测试。
首先,我们要对问题定位而不是盲目的开启什么慢日志,在并发量大并且大量SQL性能低的情况下,开启慢日志无意是将MySQL推向崩溃的边缘。
当时遇到这个情况,分析了当前的数据量、索引情况、缓存使用情况。目测数据量不大,也就几百万条而已。接下来就去定位索引、缓存问题。
经过询问,发现很多查询都是走MySQL,没有用到缓存。既然没有用到缓存,则是大量请求全部查询MySQL导致,可以通过下面的命令查看:
sqlshow processlist;
以此来找出哪些查询可能是瓶颈,并据此进行优化。
通常我们通过 Top
检查发现 mysql CPU 或者 io wait 过高 那么解决这些问题都离不开 show processlist
。show processlist
是显示用户正在运行的线程,需要注意的是,除了root用户能看到所有正在运行的线程外,其他用户都只能看到自己正在运行的线程,看不到其它用户正在运行的线程。除非单独个这个用户赋予了PROCESS
权限。
注意
show processlist
只显示前100条 我们可以通过 show full processlist
显示全部。
show processlist
显示的信息都是来自MySQL系统库 information_schema
中的 processlist
表。所以使用下面的查询语句可以获得相同的结果:
sqlSELECT * FROM information_schema.processlist;
SELECT * FROM information_schema.processlist WHERE TIME > 5 ORDER BY TIME DESC;
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 许可协议。转载请注明出处!