一次CPU飙升排查

现象

一个任务模块服务，突然告警，CPU使用100%，居高不下。
该模块已经很久没有修改上线了。
告警是一阵一阵的，并不是一直有。

推测

该服务只是在消费消息，应该是某个特别的消息引起CPU上涨，等到这个特别的消息消费完了之后，就恢复了。因此不仅需要找到引起问题的代码，还要找到引起问题的消息。

定位跟踪

进入告警服务实例 top -c 查看进程状态 topc结果

可以看出，是 PID 237 的 Java 进程用满了 CPU，这符合预期。

继续 top -p 237 ，查询指定PID 的资源占用情况

top_指定进程转存失败，建议直接上传图片文件

使用 ps -mp 237 -o THREAD,tid,time | sort -rn ，查看进程的线程情况，将该进程下的线程按资源使用情况倒序展示：

进程中的线程信息

全部线程的 CPU 使用都是 0，一共 424 个线程。

使用printf "%x\n" PID命令，将PID转为十六进制的TID

PID2TID

用 jstack 查看线程状态，

jstack 237 太多看不完

统计线程状态

jstack 237 | grep "java.lang.Thread.State" | grep "WAITING" | wc -l

结果是 387 ，大部分都在 waiting, 这时需要看一下那些运行中的线程

jstack 237 | grep -C 10 "java.lang.Thread.State: RUNNABLE"

结果同样有很多，但是有几个很明显的是业务代码的调用栈：

jstack

看到这个线程名字，ConsumeMessageThread_task-comment-remove-input-consumer-group_3 应该就是 task-comment-remove-input-consumer-group 这个消费组的消息，上面写着的 cpu=4583594.13ms 意味着占用CPU很久了，应该就是这个地方导致CPU飙升了。

事实上，看到RocketMQ的源代码里，生成监听消息线程的时候，正式按照 ConsumeMessageThread_[消费组名称]_[编号] 这样的规则命名。

这样距离找到问题很近了。

at java.util.regex.Pattern$CharPredicate.lambda$negate$3(java.base@11.0.11/Pattern.java:5687)
        at java.util.regex.Pattern$CharPredicate$$Lambda$148/0x00000001001cf840.is(java.base@11.0.11/Unknown Source)
        at java.util.regex.Pattern$BmpCharPredicate.lambda$union$3(java.base@11.0.11/Pattern.java:5701)
        at java.util.regex.Pattern$BmpCharPredicate$$Lambda$1075/0x00000001009dd040.is(java.base@11.0.11/Unknown Source)
        at java.util.regex.Pattern$CharPropertyGreedy.match(java.base@11.0.11/Pattern.java:4297)
        at java.util.regex.Pattern$BmpCharProperty.match(java.base@11.0.11/Pattern.java:3964)
        at java.util.regex.Pattern$Branch.match(java.base@11.0.11/Pattern.java:4749)
        at java.util.regex.Pattern$GroupHead.match(java.base@11.0.11/Pattern.java:4804)
        at java.util.regex.Pattern$Curly.match1(java.base@11.0.11/Pattern.java:4432)
        at java.util.regex.Pattern$Curly.match(java.base@11.0.11/Pattern.java:4381)
--
        - parking to wait for  <0x00000000c2fd0d38> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
        at java.util.concurrent.ArrayBlockingQueue.take(java.base@11.0.11/ArrayBlockingQueue.java:417)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
        at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

找到这个消息的消费者，里面有两个handler，分别是 TaskActionEnum.COMMENT_CREATE 和 TaskActionEnum.THREAD_COMMENT_COUNT

其中只有 CommentCreateTaskActionHandler 里面有正则相关的代码：


private static final String TAG_REG_EXP = "<(a|video|img)\\s+data-type=.*?data-value=.*?(/>|>[\\s\\S]*(</(img|video|img)>))";
 
private String getPureContent(TaskCommentDTO TaskCommentDTO) {
        Pattern p1 = Pattern.compile(TAG_REG_EXP);
        Matcher matcher1 = p1.matcher(TaskCommentDTO.getContent());
        String result = matcher1.replaceAll("");
        result = ContentUtils.pure(result);
        return result;
    }

基本锁定这个地方的问题了。

找到 nid=0x41cf

把 jstrack 日志打印下来后，检索刚才找到的 nid=0x41cf 的调用栈

cat jstack.log | grep -A 100 "nid=0x41cf"

locate_code

可以看到经过的业务代码，也就是上面锁定的地方，验证了上面的推测。

CPU飙升原因

这个服务跑了也有一段时间没改，突然出问题，而且过一段时间就没了，结合上面找到的正则代码，可以判断是某个消息导致这个正则运行超时了。

找到导致问题的消息

2023-08-02 15:40:05,243 [] [ConsumeMessageThread_task-comment-remove-input-consumer-group_1] INFO c.o.c.o.s.t.a.msg.consumer.TaskUGCEventConsumer$$EnhancerBySpringCGLIB$$46cfefc0 [TaskUGCEventConsumer.java:consumeCommentRemoveMessage:242] - 监听移除评论消息 Message = {"headers":{"ROCKET_TAGS":"COMMENT_DELETE","ROCKET_MQ_BORN_TIMESTAMP":1690924249956,"ROCKET_MQ_FLAG":0,"ROCKET_MQ_MESSAGE_ID":"7F00000100F8457E2F020642EF64CCDD","ROCKET_MQ_TRANSACTION_ID":"7F00000100F8457E2F020642EF64CCDD","ROCKET_MQ_TOPIC":"sns-overseas-comment-update-base-topic","ROCKET_MQ_BORN_HOST":"10.4.186.162","id":"9ee32b08-fe03-664f-558b-639ed329e7d2","ROCKET_MQ_SYS_FLAG":8,"contentType":{"concrete":true,"parameters":{},"subtype":"json","type":"application","wildcardSubtype":false,"wildcardType":false},"ROCKET_MQ_QUEUE_ID":0,"timestamp":1690962005045},"payload":{"commentKeyList":[{"id":1385859263439568905,"tid":1379986859731451911},{"id":1385859604067385352,"tid":1377760549147770886},{"id":1385863623577960455,"tid":1377672253444980745},{"id":1385863923982401539,"tid":1377257102560460809},{"id":1385866054042910726,"tid":1382112132425842697},{"id":1387964217860030467,"tid":1365272793012240384},{"id":1387964415755681793,"tid":1377672253444980745},{"id":1387964477554556932,"tid":1373650520241078274},{"id":1387964535394009097,"tid":1377760549147770886},{"id":1387964613886214147,"tid":1379986859731451911},{"id":1387964686590279688,"tid":1377257102560460809},{"id":1387964737299415046,"tid":1371469142204350468},{"id":1387964791640817665,"tid":1382112132425842697},{"id":1387966047130222597,"tid":1382182651384823815},{"id":1387966584118575112,"tid":1377480406198124552},{"id":1387967154065768456,"tid":1371472311227514883},{"id":1388235730030952450,"tid":1367767951662383110},{"id":1388236645563629573,"tid":1379641592545017862},{"id":1388236699259109384,"tid":1380877456113664009},{"id":1388237011491487745,"tid":1377251871072190472},{"id":1388237503516901385,"tid":1379555694541275144}],"status":0}}

里面是删除很多个评论的消息，处理代码的逻辑是从这些含有html标签的内容里提取出纯文字内容，拿出上面消息里的几个评论看了一下，基本都是下面几个特点：

内容全是广告链接，这也是为何被删
内容超级长，比平时的正常评论长很多倍

找到原因

把这里出问题的评论内容和正则匹配拿出来，单独测试，确实是正则匹配耗时非常久：

<(a|video|img)\s+data-type=.*?data-value=.*?(/>|>[\s\S]*(</(img|video|img)>))

想尝试优化一下，把一个匹配超时的例子（内容超长）和正则拿去网站 regex101.com/ 上测试，发现无法匹配。

于是缩短至最简单的一个标签，依然不行。仔细看，原来是正则表达式写错了，结束标签有两个img </(img|video|img)>，其中应该有一个是a，终于找到原因了。

耗时很长原理

Java 的正则匹配机制，是用 NFA 自动机，这里面有自动回溯机制，大意是，匹配时会根据表达式一直匹配下去，如果没有，就回溯，回到前面，再开始匹配。

在这个出问题的例子里面，有大量的 a 标签，前半的 a 标签总是能匹配成功，但是后面却没有，导致一直找不到结果，一直回溯，造成类似一个个字母往前挪，每个字母都要跑完真个字符串来匹配，会非常消耗CPU。

以前正常的评论都比较短，没有引起比较明显的性能问题，但是这些广告的长度长上百倍，这个就是量变引起质变，把CPU干烧脑了。

改正后，在本地单独测试，速度飞快，正常了。就算是这种超长的广告内容，只要正则写的正确，也可以很快跑出结果的。

解决

更正正则表达式，把 img 标签换回 a 标签

<(a|video|img)\s+data-type=.*?data-value=.*?(/>|>[\s\S]*(</(a|video|img)>))

参考资料

# 一个正则表达式引发的血案，让线上CPU100%异常！

一次正则引起的CPU100%问题排查