Routine Load导致CPU利用率突增（达到5000%以上）

💬 StarRocks 用户问答 数据导入与导出
#1

【详述】
三台BE节点（500GB内存，128 CPU核心），每过一个小时左右就会有1~2分钟左右的CPU突刺，如下图

image
image1833×636 107 KB

另外两台机器的监控情况也类似

我们的监控日志里面显示，这些CPU均是被BE进程占用了：

image
image489×761 40.1 KB

目前StarRocks中只有1000个通过Routine Load接入的实时表，基本无其他负载（新集群），所以初步判断是这些Routine Load任务导致的CPU利用率突增

再查看BE日志，发现每到高峰时，执行计划fragment数量就会突增，从500~2000左右增加到10000以上，日志内容大概如下：
I0508 20:53:14.277118 120646 fragment_executor.cpp:158] Prepare(): query_id=e0d4ac92-ee03-11ed-9009-e43d1a1b411c fragment_instance_id=e0d4ac92-ee03-11ed-9009-e43d1a1b411f backend_num=0

I0508 20:53:14.280663 120703 fragment_executor.cpp:158] Prepare(): query_id=e0d4ac92-ee03-11ed-9009-e43d1a1b411c fragment_instance_id=e0d4ac92-ee03-11ed-9009-e43d1a1b411e backend_num=2

I0508 20:53:14.356686 120533 fragment_executor.cpp:158] Prepare(): query_id=e0dff733-ee03-11ed-9009-e43d1a1b411c fragment_instance_id=e0dff733-ee03-11ed-9009-e43d1a1b411f backend_num=3

I0508 20:53:14.443708 120706 fragment_executor.cpp:158] Prepare(): query_id=e0ed8bc6-ee03-11ed-9009-e43d1a1b411c fragment_instance_id=e0ed8bc6-ee03-11ed-9009-e43d1a1b411e backend_num=2

I0508 20:53:14.513199 120635 fragment_executor.cpp:158] Prepare(): query_id=e0f8af57-ee03-11ed-9009-e43d1a1b411c fragment_instance_id=e0f8af57-ee03-11ed-9009-e43d1a1b4120 backend_num=0

【背景】做过哪些操作？
Create了1000个Routine Load Job，其中40个的并发task数目是3，其他均为1
【业务影响】
无
【StarRocks版本】
2.5.3
【集群规模】
3fe+3be（fe与be混部）
500GB内存，128 CPU核心
【表模型】
均为主键模型，Kafka的topic中UPSERT和DELETE操作都有

【导入或者导出方式】
Routine Load
【联系方式】
StarRocks社区群4-Matata
【附件】

Checkpointer重放Statistics相关Journal导致CPU突刺（达到5000%以上）
#2

有没有10分钟的调度任务？发个be日志看下？

#3

没有调度任务，整个系统只有1000个Routine Load任务

日志私发给您了，因为日志量太大了，只取了前后十分钟的日志，非常感谢您帮忙看看~~

#4

CPU升高的时间点是图中9:22（和BE的服务器时差是12个小时，所以日志里面是21:22）左右，持续了1分钟就恢复了

image

#5

fe.audit.log中查下e209fba9-ee07-11ed-9009-e43d1a1b411c这个query id对应的query是啥

#6

或者把对应时间点的fe.audit.log发下

#7

很奇怪，这个QueryID查不到任何在fe.audit.log中的日志，所有的3个FE节点都查了

范围扩大到fe.log的话，只有下面两条日志：
2023-05-08 21:21:55,049 INFO (ForkJoinPool.commonPool-worker-19|4957258) [QeProcessorImpl.registerQuery():81] register query id = e209fba9-ee07-11ed-9009-e43d1a1b411c, job: -1

2023-05-08 21:21:57,293 INFO (ForkJoinPool.commonPool-worker-19|4957258) [QeProcessorImpl.unregisterQuery():91] deregister query id e209fba9-ee07-11ed-9009-e43d1a1b411c

#8

目前还发现了一个规律，那就是每次CPU利用率突增的时候，都是FE Leader在进行Checkpoint的时候，但是还不清楚这两者的具体关系是什么

#9

1000个Routine Load任务，这个任务数算是非常大了，怀疑可能是高频导入触发了统计信息表的高频更新，统计信息表在一段时间里通过频繁clone累积了很多rowset，直到compaction发生。这个PR优化了频繁clone时compaction不及时的问题 https://github.com/StarRocks/starrocks/pull/20760 )，可以考虑升级到 2.5.5 再观察一下

#10

@Doni 大佬好，非常感谢回复，还是想请教一下，有什么日志或者办法能佐证一下这个判断嘛

#11

可以看看 日志中有没有统计表相关的 too many versions，另外统计信息更新会有个 union all的大查询，rowset数量多的话，CPU会消耗在olap scan相关的路径上，可以日志中搜 OLAP_SCAN找对应的sql看一下具体的profile

#12

大佬你好，我搜了too many versions 和 OLAP_SCAN 相关的日志，没找到记录，好像不是这个原因。

我目前还发现了一个规律，那就是每次CPU利用率突增的时候，都是FE Leader在进行Checkpoint的时候，但是看了部分代码，还不清楚这两者的具体关系是什么。大佬有什么想法吗

#13

cpu突增的时候，先 top 看下哪些进程cpu占用较高，如果是be或者fe进程，再执行 perf 看一下哪个函数之类的占用高（如果跟checkpoint有关的话，应该是fe进程cpu占用较高），可以三台机器都看一下

#14

好的，非常谢谢大佬的建议

#15

已找到原因并解决，具体查看： Checkpointer重放Statistics相关Journal导致CPU突刺（达到5000%以上） - :speech_balloon: StarRocks 用户问答 / 性能相关 - StarRocks中文社区论坛 (mirrorship.cn)

京ICP备2022026421号-1