10 月 29 日下午两点四十,日志清洗服务的四个 Pod 在两分钟内先后被 CPU 限流打到不可用。上游积压,告警一路串到值班群。这篇是那次故障的复盘。
现象
特征很怪:
- CPU 100%,但内存平稳,GC 正常。
- QPS 没有上涨,反而因为处理不过来在下降。
- 重启后恢复几分钟,然后再次打满。
- 四个 Pod 不是同时挂的,间隔几十秒。
「重启后恢复一段时间又复发」通常指向两类原因:资源泄漏,或者某类特定输入触发了慢路径。内存平稳排除了前者,所以重点转向后者。
定位
第一步是确认 CPU 花在哪个线程上:
top -H -p $(pgrep -f cleaner.py)
结果是单个工作线程吃满一个核。接着用 py-spy 直接对运行中的进程采样,不需要改代码、不需要重启:
py-spy dump --pid 1 --locals
py-spy record --pid 1 --duration 30 --output flame.svg
dump 的输出把问题指得清清楚楚:
Thread 0x7F2A (active)
_compile_and_match (re/__init__.py:190)
extract_ua (cleaner/parsers.py:88)
Locals:
pattern: '^(\\w+[\\s/]*)+\\(([^)]*)\\)$'
line: 'Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 KHTML like Gecko ...'
栈几乎不动,一直停在同一个 re.match 上。这就是灾难性回溯。
py-spy 需要 SYS_PTRACE 能力才能读取目标进程内存。在 Kubernetes 里可以用 kubectl debug 起一个带该能力的临时容器,共享目标 Pod 的进程命名空间,不必给业务容器长期开这个权限。
为什么会指数级
罪魁是 (\w+[\s/]*)+ 这种嵌套量词:一个可重复的组,里面还有可重复、且能匹配空串的部分。
Python 的 re(以及 Java、JavaScript、PCRE)用的是回溯式引擎。匹配失败时,它会退回上一个分支点换一种切分方式再试。对于 (\w+)+ 这样的结构,字符串 aaaa 可以被切成 a|a|a|a、aa|a|a、aa|aa、aaa|a、aaaa……n 个字符有 2n-1 种切分方式。只要整体最终匹配失败,引擎就会把这些方式全部试一遍。
在这次故障里,末尾的 \(([^)]*)\)$ 要求以右括号结尾。绝大多数 UA 字符串括号在中间,结尾是版本号,于是必然失败——每一条这样的日志都会触发一次完整的指数级搜索。
写个脚本量化一下:
import re, time
pattern = re.compile(r'^(\w+[\s/]*)+\(([^)]*)\)$')
for n in range(18, 30):
s = 'a' * n + '!' # 末尾字符保证匹配失败
t0 = time.perf_counter()
pattern.match(s)
print(f'{n:3d} 字符 {time.perf_counter() - t0:.3f}s')
18 字符 0.011s
20 字符 0.043s
22 字符 0.172s
24 字符 0.688s
26 字符 2.751s
28 字符 11.004s
每多两个字符,耗时翻两番。一条 120 字符的 UA 意味着这个进程再也不会返回了。
那为什么之前一直没事?因为这个正则跑了一年多,一直只处理内部埋点上报的 UA,格式固定。故障当天上游接了一个新数据源,UA 来自真实浏览器,长度和结构都不一样。代码没变,输入变了。
三种修法
一、重写正则,消除歧义
最彻底的办法。原意是「若干个由空白或斜杠分隔的词,后面跟一个括号内容」,可以写成没有歧义的形式:
# 有歧义:\w+ 和 [\s/]* 的边界可以有多种划分
r'^(\w+[\s/]*)+\(([^)]*)\)$'
# 无歧义:分隔符必须至少出现一次,且两部分字符集不重叠
r'^\w+(?:[\s/]+\w+)*\s*\(([^)]*)\)$'
关键在于让每个字符只可能属于一个部分。\w 和 [\s/] 本来就不重叠,问题出在 * 允许分隔符为空,导致「一个词」和「两个词中间零个分隔符」无法区分。改成 + 就断掉了这条歧义。
二、换一个不回溯的引擎
Python 的 regex 第三方库支持原子组和占有量词,匹配失败后不再回退:
import regex
pattern = regex.compile(r'^(?>\w+[\s/]*)+\(([^)]*)\)$')
Go 和 Rust 的标准正则库用 RE2 类算法,时间复杂度对输入长度线性,天然免疫这类问题——代价是不支持反向引用和前后瞻。如果服务是纯文本处理且不需要这些特性,选型时就该优先考虑。
三、加护栏
前两条修的是这一处,护栏防的是下一处。我们加了两层:
MAX_UA_LEN = 512
def extract_ua(line: str):
if len(line) > MAX_UA_LEN:
return None # 超长直接放弃,记一次指标
return pattern.match(line)
以及在进程级别加了超时。Python 的 re 不支持匹配超时,只能靠信号(仅主线程可用)或者把解析放进独立进程池并设 timeout:
from concurrent.futures import ProcessPoolExecutor, TimeoutError
with ProcessPoolExecutor(max_workers=4) as pool:
fut = pool.submit(extract_ua, line)
try:
result = fut.result(timeout=0.2)
except TimeoutError:
slow_regex_counter.inc()
result = None
进程池的额外好处是失控的匹配可以被真正杀掉;线程池做不到,因为 re 在匹配期间不释放 GIL,也不响应中断。
怎么在上线前发现
事后我们在 CI 里加了两道检查。
一是静态扫描。Semgrep 有现成规则,也可以用 dlint;对于 JavaScript 项目,ESLint 的 no-unsafe-regex 或者 eslint-plugin-redos 更成熟。
二是对项目里所有正则做一次模糊测试,用递增长度的构造串测耗时:
import re, time, pytest
from cleaner import parsers
FUZZ_CHARS = ['a', 'a ', 'a/', '(', 'aa\t']
@pytest.mark.parametrize('name,pat', parsers.ALL_PATTERNS.items())
def test_no_catastrophic_backtracking(name, pat):
for ch in FUZZ_CHARS:
s = ch * 40 + '!'
t0 = time.perf_counter()
re.compile(pat).match(s)
elapsed = time.perf_counter() - t0
assert elapsed < 0.05, f'{name} 在 {ch!r}*40 上耗时 {elapsed:.3f}s'
这个测试跑得很快,而且当场就抓出了另外两个有同样问题的正则——都在少用的分支里,暂时没被触发而已。
几条结论
- 看到
(X+)+、(X*)*、(X|Y)+且 X 与 Y 有交集,就要警惕。 - 回溯只在匹配失败时爆炸。测试用例里必须包含不匹配的输入,只测正例发现不了问题。
- 「代码没改过所以不可能是它」是这次排查里最大的思维阻碍。输入分布的变化和代码变更一样是变更。
- 处理外部输入的正则一律要有长度上限,这是成本最低的一道防线。