以前写过一篇博客怎么用idea分析hprof文件定位JVM内存问题 。然后有小伙伴私信说要怎么定位Jar包CPU高占用的问题。正好最近有个真实场景感觉很不错记录一下。我是从定位Java进程开始。如果你能确定你的Java进程和项目那就跳过第一步。一、定位Java进程top是定位服务器资源使用率最好用的工具之一想了解的可以去搜搜它的使用和具体参数含义。现在我们最主要关注的几个参数我用红框起来了记住它的PID。本示例即25238901.1 分析占用us用户态77.7% sy内核态12.3%几乎无空闲。%CPU107.6%说明它占用了超过一个物理核。wa接近 0这里其实就能初步判断问题在 JVM 应用内部不是系统 IO 等待。1.2 定位具体Jar包如果你的服务器上只跑了一个Jar包那就不用这步操作了肯定是它。但如果不只跑了一个Jar包那就可以去定位一下到底是哪个Jar包# 自行调整PIDcat/proc/2523890/cmdline|tr\0 这样就能定位到具体的Jar包了我这边是inspection-platform-test.jar这个Jar。二、找到具体线程找到Jar包之后我们要继续定位是这个Jar的什么线程导致的。2.1 查看进程内线程 CPU 占用我们可以继续用top去查看这个进程下的所有线程top-Hp2523890很容易我们就定位到了三个线程my-task-schedul分别占31.6%、26.3%和21.1%合计近 90%。TIME累计 CPU 时间达到 100 分钟说明是持续性的不是偶发 spike。其他线程Redisson、GC ThreadCPU 很低初步排除其他问题。⚠️ 注意top的COMMAND列只显示前 15 个字符线程名可能被截断。实际线程名可能是my-task-scheduling-1这种更长的名字。值得一提的是这个前缀在我的系统内是定时任务的专用线程池的线程前缀定位起来就有个大方向了。因此也建议没有配置线程池线程名称前缀的小伙伴配置起来后续在定位问题方面会方便非常多。三、抓取 Java 线程栈第一步是定位Jar的进程号第二步是定位现在我们定位到了是my-task-schedul这个线程池导致的问题。但这里面范围还是很大因此我们可以继续去定位具体的堆栈。3.1 抓栈建议多抓几次间隔 3~5 秒便于观察线程状态变化jstack-l2523890/tmp/jstack_1.logsleep3jstack-l2523890/tmp/jstack_2.logsleep3jstack-l2523890/tmp/jstack_3.log之后我们就可以根据这个日志来定位堆栈了。3.2 搜索目标线程的两种方式找到高 CPU 线程的 PID 后下一步就是在jstack里找到对应的线程栈。一般有两种搜索方式。方式一按线程名模糊搜索推荐先做这个适合先整体看看这个线程池里有哪些线程、分别是什么状态grep-itask-sched/tmp/jstack_1.log|head-n20输出示例这里能直接看到哪些线程是runnable正在干活重点关注哪些线程是waiting on condition空闲或等下一次调度每个线程的nid就是操作系统线程 ID和top -Hp里的 PID 是一回事。方式二按具体 PID / nid 精确搜索已经确定某个 PID 高 CPU 后直接查这个线程的完整栈# 注意 nid 后面加个空格避免 2525536 匹配到 25255360grep-A100nid2525536 /tmp/jstack_1.log-A 100表示把匹配行后面 100 行也打出来。关于 nid 的格式jstack里nid的显示格式可能是十进制也可能是十六进制不同 JDK 版本表现不一样。老版本 JDK 常见这样thread-xxx #12 nid0x268961 ...而 Java 21 OpenJDK 可能直接显示十进制my-task-scheduling-5 #96 ... nid2525534 ...所以先看一下你的jstack输出里nid是什么格式如果是十进制直接拿top -Hp里的 PID 搜就行如果是十六进制带0x前缀需要把 PID 转一下printf%x\n2525537# 268961grep-A100nid0x268961/tmp/jstack_1.log3.3 搜索为空的常见原因如果按nid搜不到通常有两个原因top和jstack不是同一时刻抓的线程可能被回收重建PID 变了nid格式没对上十进制和十六进制搞混了。解决办法重新同时抓top -Hp和jstack或者先用线程名模糊搜索确认当前线程的nid。四、分析线程栈找到线程之后最重要的就是看懂jstack里的栈信息从而判断这个线程到底在干什么。4.1 jstack 输出格式一条典型的线程栈长这样my-task-scheduling-5 #96 [2525534] daemon prio5 os_prio0 cpu5351201.84ms elapsed65557.81s tid0x00007ff13737e280 nid2525534 runnable [0x00007ff090cfd000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.Net.poll(java.base21.0.12/Native Method) at sun.nio.ch.NioSocketImpl.park(...) at java.net.Socket$SocketInputStream.read(...) at com.mysql.cj.jdbc.ClientPreparedStatement.execute(...) at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(...) ...几个关键字段字段含义my-task-scheduling-5线程名#96JVM 内部线程编号[2525534]操作系统线程 IDTID和top -Hp里的 PID 对应nid2525534也是操作系统线程 ID十六进制写法是nid0x268961cpu5351201.84ms该线程累计消耗的 CPU 时间java.lang.Thread.State线程状态RUNNABLE / WAITING / TIMED_WAITING / BLOCKEDat ...调用栈从下往上是调用顺序4.2 线程状态怎么看状态含义是否可能耗 CPURUNNABLE正在运行或等待 CPU/IO可能高 CPUWAITING无限等待某个条件/锁一般不耗 CPUTIMED_WAITING限时等待比如Thread.sleep、wait(timeout)一般不耗 CPUBLOCKED等待监视器锁竞争激烈可能伴随高 CPU高 CPU 场景下我们重点看RUNNABLE的线程BLOCKED多了说明有锁竞争。4.3 定位到业务代码比如这次排查中一个线程的栈顶是这样的at sun.nio.ch.Net.poll(...) at java.net.Socket$SocketInputStream.read(...) at com.mysql.cj.jdbc.ClientPreparedStatement.execute(...) at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(...) at java.lang.reflect.Method.invoke(...) at org.apache.ibatis.plugin.Plugin.invoke(...)可以继续把grep -A的行数加大比如-A 80、-A 100继续往下翻grep-A100nid2525534 /tmp/jstack_new.log继续往下就能看到at com.ny.insp.dao.IpDroneArchiveDao.updateOnlineStatus(IpDroneArchiveDao.java:153) at com.dji.sample.manage.service.impl.DeviceOfflineLogScheduledService.updateOnlineStatus(...) at com.dji.sample.manage.service.impl.DeviceOfflineLogScheduledService.checkDevice(...) ... at org.springframework.scheduling.support.ScheduledMethodRunnable.run(...)到这里就清晰了这是一个 Spring 定时任务在逐条更新数据库。那后续就是优化一下这部分的业务代码了这里就不提了。4.4 常见高 CPU 栈顶场景栈顶特征可能原因处理方向栈顶是你自己的业务类比如比如 com.xxx.service.XxxService.someHeavyMethod死循环、大量计算、大数据量遍历直接看代码逻辑栈顶是java.net.SocketInputStream.read/com.mysql.cj...SQL 慢查询、N1 查询、大结果集查 MySQL 慢日志、加索引、批量查询栈顶是GC Thread#*/VM Thread频繁 GC / Full GCjstat -gcutil、jmap -histo分析内存栈顶是sun.nio.ch.Net.poll/SelectorImplNetty / NIO 事件循环看连接数、消息量是否过大栈顶是jdk.internal.misc.Unsafe.park线程池线程空闲等待一般不是它导致 CPU 高栈顶是java.util.concurrent.locks锁竞争检查锁粒度、并发控制五、辅助排查手段jstack定位到大致方向后通常还需要结合其他工具确认根因。5.1 看 GC 是否正常如果top -Hp里高 CPU 的是GC Thread#0、GC Thread#1这类 JVM 线程优先看 GCjstat-gcutil2523890100010输出示例S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 75.00 95.00 97.50 95.20 1234 12.345 89 56.789 69.134重点关注O老年代是否接近 100% 且下不来FGC次数是否快速增长FGCTFull GC 总时间是否持续增加。如果老年代快满了、FGC 很频繁基本是内存泄露或堆内存配小了。5.2 看内存里的对象排行jmap-histo:live2523890|head-n30这个命令会打印存活对象数量排行。如果某个业务对象数量异常多比如SomeEntity、byte[]、HashMap$Node暴增就能快速定位到内存热点。5.3 看数据库慢查询如果栈里卡在 MySQL一定要去数据库侧确认-- 看当前正在执行的 SQLSHOWFULLPROCESSLIST;-- 看慢查询汇总需要 performance_schemaSELECTDIGEST_TEXT,COUNT_STAR,SUM_TIMER_WAIT/1000000000000AStotal_seconds,AVG_TIMER_WAIT/1000000000000ASavg_secondsFROMperformance_schema.events_statements_summary_by_digestORDERBYSUM_TIMER_WAITDESCLIMIT10;很多时候Java 侧 CPU 高其实是 MySQL 慢查询导致的线程卡在等 SQL 结果或者一遍又一遍地执行慢 SQL。5.4 看业务日志最后别忘了看应用日志特别是异常、超时、重复重试相关的日志tail-f/path/to/app.loggrep-EERROR|Exception|timeout|rejected/path/to/app.log|tail-n50如果你的日志链路带了 traceId可以直接用 traceId 把一次请求的完整链路串起来。背八股还是有点用的好像。。六、完整排查 Checklist最后整理一个可以照搬的排查流程top看整体 CPU、内存、wa确认是用户态高还是 IO 等待高。cat /proc/PID/cmdline确认是哪个 Jar 包。top -Hp PID找到具体高 CPU 的线程记录线程 PID。jstack -l PID /tmp/jstack.log抓线程栈。看jstack里nid是十进制还是十六进制如果是十进制直接用 PID 搜如果是十六进制带0x再用printf %x\n转换。grep -A 80 nid... /tmp/jstack.log查看目标线程栈必要时把-A加大到 100。从下往上找业务代码穿透 MyBatis / Spring 代理 / 反射层。判断线程状态RUNNABLE看栈顶在干什么BLOCKED看锁竞争WAITING一般不是 CPU 元凶。结合辅助工具jstat看 GC、jmap看内存、SHOW PROCESSLIST看 SQL、日志看异常。定位到具体代码后再决定是加索引、改 SQL、拆循环、加缓存、还是调整线程池配置。七、几个关键点top线程名被截断到 15 个字符不要凭截断名搜索要结合 PID 搜nid注意 nid 可能是十进制或十六进制。top和jstack尽量同时抓调度线程池里的线程可能被回收重建不同时间抓到的 nid 可能对不上。grep -A 40可能不够MyBatis Spring AOP JDK 反射会把业务方法包得很深建议-A 80或-A 100。不要看到waiting on condition就放松警惕线程可能只是在等下一次调度但它累计 CPU 时间依然很高。RUNNABLE不一定在跑业务代码也可能卡在Net.poll等 MySQL Socket 读要结合栈顶判断。这次排查本质上就是CPU 高 ≠ 业务代码在死循环也可能是线程频繁发起慢 SQL、等 MySQL 结果。通过top定位进程 →top -Hp定位线程 →jstack定位栈 → 结合数据库/日志确认根因基本能覆盖大部分 Java 高 CPU 场景。
