一个正则表达式导致 CPU 高的问题排查过程

这篇文章记录一个正则表达是导致 CPU 高的问题排查。由于无法直接使用线上的代码测试,所以我自己把代码整理了下来,具体代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
public class AppMain {
public static void main(String[] args) throws InterruptedException {
final String regex="^([a-z0-9A-Z]+[-|\\.]?)+[a-z0-9A-Z]@([a-z0-9A-Z]+(-[a-z0-9A-Z]+)?\\.)+[a-zA-Z]{2,}$";
final String email="blog.laofu.online.fuweilao@vip.qq.com#";
for (int i = 0; i < 1000000; i++) {
Matcher matcher = RegexUtils.matcher(regex, email);
matcher.find();
Thread.sleep(10);
// matcher.group();
}
}
}

当运行程序的时候,我们可以看到 java 的进程占用了 CPU 了 82.1%,由于我使用的服务器是 1核+2G, 所以 load avg 占用也很高。

image-20201005230510905

使用 top -H -p 4214 查看各个线程占用的情况

image-20201005230556871
hex
使用 printf '%x\n' 4217 把进程转成 16 进制值为 1079。执行 jstack 4214|grep 1079 -A 100得到线程的堆栈信息:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
"main" #1 prio=5 os_prio=0 tid=0x00007f943004c800 nid=0x1079 runnable [0x00007f9439fe0000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$Curly.match0(Pattern.java:4264)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
// at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4195)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4293)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4195)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4293)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4195)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4293)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4815)
at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
at java.util.regex.Pattern$Begin.match(Pattern.java:3539)
at java.util.regex.Matcher.search(Matcher.java:1248)
at java.util.regex.Matcher.find(Matcher.java:637)
at org.rz.search.spider.AppMain.main(AppMain.java:13)

"VM Thread" os_prio=0 tid=0x00007f94300cc800 nid=0x1079 runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f9430121000 nid=0x1079 waiting on condition

JNI global references: 5

从上面的堆栈信息可以看出来是正则的递归调用,导致了很深的堆栈。
查看最终的堆栈入口:at org.rz.search.spider.AppMain.main(AppMain.java:13) 可以断定问题是正则匹配的原因。

为什么一个正则会导致CPU飙高?

我们知道,正则一般都是采用贪婪的模式,如果当前字符串不匹配,会导致字符回溯,如果待匹配串过长就会导致匹配的次数成指数上升。

正则的性能测试可以到 【正则性能测试(regex101)】

使用简单的数据匹配,比较此时已经达到了 168997次。

截屏2020-10-05 下午11.24.19

我再次增加了两个字符,比较次数已经增到 404895次。

截屏2020-10-05 下午11.25.44

当然,如果能匹配成功,则匹配的次数非常少

截屏2020-10-05下午11.25.44

所以以后使用正则的时候,应该多多注意,具体这个怎么解决,还是要根据业务场景来具体实施,我个人推荐 使用一个简单的过滤规则,把明显有问题的字符先去除

在本例中就可以直接先判断字符是否包含非法字符 #,$,-,?...等,然后再使用正则再次匹配。

一个正则表达式导致 CPU 高的问题排查过程

http://blog.laofu.online/2020-10-01-regex-cpu/

作者

付威

发布于

2020-10-05

更新于

2020-10-05

许可协议

评论