先说故障现象。凌晨两点半,监控告警群里跳出一条消息:订单服务某台实例 CPU 使用率 98%,持续五分钟以上没有回落。接着又跳了一条:接口 P99 从 80ms 飙到 3.4s,49 个请求超时。
值班同事第一反应是重启,我拦了一下。这台实例还在撑着,重启就等于把现场毁了。我跟他说了一句——先给我十分钟,别动它。
这次排查我做对了几个关键决定,最后在 30 分钟内定位到根因。整个过程值得写下来,尤其是中间差点走错方向的那一段。
第一反应:先排除 GC
CPU 打满,最常见的原因就那么几个:GC 频繁、死循环、线程死锁、死锁外的锁竞争。死锁不会导致 CPU 高,先划掉。GC 和死循环是主要嫌疑。
我 ssh 上那台机器,先看 GC 情况。JVM 启动参数里本来就带了 -Xlog:gc*:file=/var/log/app/gc-%t.log:time,tags,level:filecount=20,filesize=100M,直接 tail 日志:
tail -n 200 /var/log/app/gc-2025-01-08_00-00-00.log | grep -E "Pause Young|Pause Full"
结果很干净。最近一个小时的 Young GC 次数是 3 次,每次停顿 12-18ms,没有 Full GC。GC 日志末端的时间戳就在两分钟前,说明日志还在正常滚动。
这基本就排除了 GC 是老大的可能。如果是 GC 导致的 CPU 打满,日志里会刷满 Young GC 记录,并且间隔越来越短,从几分钟一次变成几秒一次。我们这里完全没有这个现象。
那就剩下死循环或者大量计算。
jstack 抓了三次,看到一个共同点
先上 jstack。这里有个经验:jstack 采样一次几乎没用,因为你抓到的是一个瞬间快照,死循环反而不停在几个点循环,单次快照只能看到它当下在哪一行,看不出规律。要连续抓几次做对比。
for i in 1 2 3; do
jstack -l 18342 > /tmp/stack-$(date +%s).txt
sleep 1
done
拿到三个文件之后,先数 RUNNABLE 状态的线程:
grep -c "java.lang.Thread.State: RUNNABLE" /tmp/stack-*.txt
三次都稳定在 200 多个。按理说一个 4 核的机器上 Tomcat 线程池下 200 多个线程同时 RUNNABLE,这不正常。
顺手看一下都在干什么:
grep -A 5 "java.lang.Thread.State: RUNNABLE" /tmp/stack-1704723891.txt
| grep "at com.xxx" | sort | uniq -c | sort -rn | head -20
结果出来了,二百多个线程堆在同一个地方:
189 at java.util.regex.Pattern$Loop.match(Pattern.java:4919)
189 at java.util.regex.Pattern$GroupHead.match(Pattern.java:4825)
189 at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
189 at java.util.regex.Pattern$Curly.match0(Pattern.java:4493)
189 at java.util.regex.Matcher.match(Matcher.java:1381)
189 at java.util.regex.Matcher.matches(Matcher.java:601)
189 at com.shop.order.validator.AccountValidator.checkEmail(AccountValidator.java:47)
同一行代码,189 个线程。到这里基本就锁定方向了:某个地方在跑正则,而且卡在 Pattern$Loop.match——这个类名是回溯匹配的关键类。
但 jstack 的坑还在
jstack 只告诉我”在跑正则”,不告诉我具体在处理什么输入。也就是说我看到了”是什么方法”,但看不到”是什么参数”。而定位根因必须知道输入。
有两条路:要么在代码里加日志(但已经来不及改代码,改完还得重启);要么换更强的工具,把 CPU 时间切片采样出来,看看具体调用链和输入范围。
我选了第二条,用 async-profiler。
async-profiler:装好就能起飞
async-profiler 的安装极其简单。去 GitHub release 下个压缩包(最新版 4.x 就够),解压到任意目录,用 Java 进程的 PID 直接跑。它不需要 attach jvm,不依赖 JDWP,而且用的是 perf_events 加 AsyncGetCallTrace,采样开销极低(5% 以内)。
cd /tmp
wget -c https://github.com/async-profiler/async-profiler/releases/download/v4.0/async-profiler-4.0-linux-x64.tar.gz
tar -zxf async-profiler-4.0-linux-x64.tar.gz
cd async-profiler-4.0-linux-x64
./profiler.sh -e cpu -d 30 -f /tmp/cpu.html 18342
几个参数解释一下。-e cpu 表示采 CPU 使用(也有 alloc 采内存分配、lock 采锁竞争)。-d 30 采样 30 秒。-f /tmp/cpu.html 输出成一个可交互的 HTML 文件,直接用浏览器打开看。18342 是 Java 进程 PID。
30 秒之后生成文件,我下载到本地用 Chrome 打开。
火焰图怎么读
第一次看火焰图的人容易懵。其实规则就三条。
横轴是 CPU 占用比例。每一块越宽,说明这个调用栈在采样里出现的次数越多。横轴不是时间,不要把左右理解成先后顺序。
纵轴是调用栈深度。最底下是主线程或者线程池的入口,越往上越深,最上面那片”屋顶”是 CPU 真正花在的地方。
同一个方框内颜色通常无意义,只是为了区分相邻的帧。你要找的是最宽的那个”平顶山”。
我打开这张图,一眼就看到了一个巨大的红色方块,占了整张图的 96%。放大之后看调用栈:
Thread.run
└─ ThreadPoolExecutor$Worker.run
└─ Tomcat Thread
└─ ... (省略若干)
└─ AccountValidator.checkEmail
└─ Matcher.matches
└─ Pattern$Loop.match
└─ Pattern$Loop.match (这里堆了 40 多层)
└─ ...
中间那个 Pattern$Loop.match 递归调用了几十层,这是正则回溯的典型特征。线性匹配不会堆这么深。
正则回溯爆炸是什么
到这里就能解释现象了。但为了给团队里其他人讲清楚,我花了两小时把背后的原理和一个复现案例整理了一下,正好写进这篇文章。
先看当时的代码,简化后是这样:
// AccountValidator.java:47
public static boolean checkEmail(String email) {
String regex = "^([a-zA-Z0-9]+[_|\_|\.]?)*[a-zA-Z0-9]+"
+ "@([a-zA-Z0-9]+[_|\_|\.]?)*[a-zA-Z0-9]+\.[a-zA-Z]{2,3}$";
return email.matches(regex);
}
这条正则是我从某个开源项目里抄来的,当年大家觉得”能验证邮箱就行”,也没多想。网上流传的那条”最权威的邮箱正则”接近这个结构。
它的核心毛病在于:([a-zA-Z0-9]+[_|_|.]?)* 这一组里有两个量词叠加。[a-zA-Z0-9]+ 是一个加号量词,外面又套了一层星号量词。这在正则引擎里会触发”回溯爆炸”——也叫 catastrophic backtracking。
当输入是一个合法邮箱的时候,正则匹配路径唯一,跑得飞快。但当输入是一串单调重复的字符(比如 30 个 a,或者 aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa 后面带一个非法的字符),正则引擎就会把这个长串拆分成所有可能的组合去尝试:
先试 1+29、再试 2+28、再试 3+27……每一种组合又要再继续细分。字符串长度每增加 1,组合数几乎翻倍。这就是指数级复杂度,30 个字符的时候还需要跑大约 2^30 次回溯,约十亿次操作。100 个字符?根本算不完。
而我们的系统有个什么背景——用户注册、改绑邮箱、找回密码,都会走这条校验。有人(也可能是脚本)提交了一个 200 字符的非法邮箱,直接把 Tomcat 线程池打满。
本地复现,验证猜想
我先写了一个最简的复现,跑在一个只有 main 方法的 Java 文件里。用 jshell 更快,不用建工程:
jshell> String regex = "^([a-zA-Z0-9]+[_|\_|\.]?)*[a-zA-Z0-9]+@x\.y$";
jshell> String input = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa";
jshell> long s = System.currentTimeMillis();
jshell> boolean r = input.matches(regex);
jshell> System.out.println("耗时: " + (System.currentTimeMillis() - s) + "ms");
耗时: 2847ms
32 个字符,耗时将近 3 秒。把字符串加到 40 个字符,需要跑将近 10 分钟。这就是线上 CPU 200% 的真相。
顺手做个对照,把正则换成一条安全的版本:
jshell> String safe = "^[a-zA-Z0-9._%+-]+@[a-zA-Z0-9.-]+\.[a-zA-Z]{2,}$";
jshell> long s = System.currentTimeMillis();
jshell> "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa".matches(safe);
jshell> System.out.println("耗时: " + (System.currentTimeMillis() - s) + "ms");
耗时: 0ms
同一份输入,安全版本 0 毫秒。
修复与善后
根因实锤了,改起来不难。我做了三件事。
第一件事,换正则。邮箱校验最容易踩坑的是”想要完全准确”,于是都去抄复杂的正则,反而把性能搞崩。实际上真正严谨的校验应该做发信验证(给邮箱发链接),前端能做的是”看起来像那么回事”。我们换成上面那个简单的安全版本,性能稳定在 O(n)。
第二件事,加输入长度上限。Email 的 RFC 5321 规定最大 254 个字符。我们的入参本来就在 DTO 里定义了 @Size(max = 254),但校验顺序有问题——先跑正则,后跑 Bean Validation。改成 @Pattern 直接做在 DTO 字段上,让 Bean Validation 框架统一管,天然会先走长度检查。
第三件事,加超时护栏。正则匹配本身没有超时机制,这是 Java 的短板。如果以后再出现类似的问题,全站不能因为一段正则挂掉。我们在一个统一的 RegexUtil 里给所有正则匹配套了个独立线程池,超时 200ms 直接中断,返回 false。这不是最优解(中断线程不安全),但比什么都做要好。
第三件事其实还有另一个更优雅的替代方案——用 CharSequence 包装输入,在 charAt 里做次数统计,超过阈值就抛异常。这个方案我在一些小项目里试过,效果不错,但对大多数团队来说维护成本太高,我们没采用。
修复之后的验证
改完之后先在本地压了一遍,然后上线观察。原来那台把 CPU 打满的机器,重启加载新代码之后 24 小时运行的 CPU 曲线:
日常稳态维持在 18%-22%(之前稳态是 25%,说明老正则平时就在消耗性能,只是输入短的时候没暴露)。压测接口 P99 从 3.4s 降回来了 90ms。24 小时内出现过两次毛刺到 35%,对应的是正常的批量查询任务,跟正则无关。
这件事算是过去了。但后面复盘的时候我一直在想一个问题——如果当时不是 jstack 已经抓到线索,靠什么能在 10 分钟内定位?
回头看 JFR,一个被严重低估的工具
这次我用了 async-profiler,但排完后半程我发现了另一个更好用的东西——JFR(Java Flight Recorder)。 JDK 11 之后已经开源免费,JDK 17 之后基本没什么明显开销(生产环境长期开 1% 都不到),JDK 21 上配合 jcmd 能做的事更多。
JFR 的价值在于:它可以常驻开启,不用等到故障才去装工具。对不能随便 attach 的生产环境尤其有用。
最简单的开启方式是在 JVM 参数里加:
-XX:StartFlightRecording=filename=/var/log/app/app.jfr,duration=1200s,settings=profile
duration=1200s 表示录 20 分钟。这样每次重启服务都会自动录 20 分钟,过了就自动停止。settings=profile 用的是 Profile 预设,采样频率较高但开销依旧很低(够用)。
如果不想常开,也可以故障时手动触发:
jcmd 18342 JFR.start name=diag settings=profile duration=120s filename=/tmp/diag.jfr
录完之后看事件:
jfr print --events jdk.ExecutionSample /tmp/diag.jfr | head -100
或者用更直观的方式打开生成的 .jfr 文件——JDK 自带 jmc(JDK Mission Control),是个图形界面,可以直接看火焰图、方法热点、GC 事件、锁竞争。JMC 从 JDK 11 之后要单独下载,但它读取 .jfr 的能力是官方的、无损的。
这次排查我们事后用 JFR 重新复现了一遍,产出一样的结果,只是时间点比 async-profiler 早了 15 分钟。也就是说——如果 JFR 常开着,压根不需要 jstack 采样,直接打开 JMC 看火焰图就能定位。这个认知对我很有冲击。
回去之后我给所有核心服务都加上了 JFR 常驻采样,每次录 30 分钟轮转。存储成本一天 200MB 左右,完全可接受。
还踩了两个小坑
坑一:async-profiler 默认只看 CPU,看不到 IO 等待。如果你的问题是线程在等数据库、等 HTTP 响应,火焰图上这些栈会非常窄甚至看不到,容易误判为”这地方没问题”。这种情况要换 -e wall 采墙钟,才能把 IO wait 也算进采样。-e alloc 采内存分配,-e lock 采锁竞争。这三个我建议都存一份,出问题上 JMC 一起看。
坑二:容器里跑 async-profiler 需要显式指定命名空间。我们的机器是 K8s 里的 Pod,容器环境里 async-profiler 拿到的 PID 是容器内部的。如果直接在宿主机跑一定要用容器内的 PID,否则会采到别的进程。可以用 kubectl exec 进容器里跑,简化这种麻烦。
还有一点值得提醒:jstack 和 jcmd 在 JDK 21 之后都支持 ZGC 了,但特别老版本的 JDK 8 上对 G1 抓栈会有停顿,抓一次能卡 200ms 以上。所以生产上抓 jstack 一定要连抓三次做对比,不能用单次结论,也不能在流量峰值时段密集抓。
最后总结几条经验
第一,CPU 高先排除 GC,不是先看代码。GC 日志是成本最低的排查手段,没有之一。
第二,jstack 单次没用,必须多次采样对比。看到 200 多个线程堆在同一行,基本就是答案。
第三,jstack 之后要能定位到”什么输入”。方法名告诉你哪一行,火焰图配合 JFR 才能告诉你为什么。缺一环都收不了场。
第四,正则这种”看起来无害”的东西,是最容易在生产上翻车的。凡是带嵌套量词的正则(([a-z]+)+ 这种),上线前必须做输入长度校验,否则就是一颗定时炸弹。
第五,JFR 常驻采样建议默认开启。数据成本低,收益高,比”出事再装工具”的被动模式靠谱太多。
这次故障之后我在团队里推了一条规则:所有核心服务的 JVM 启动参数里必须包含 JFR 常驻采样配置,并且保留至少 3 天的飞轮文件。真出事的时候你可以不看,但不能没有。

