【查询出现毛刺】正常查询发现不定时出现耗时较长毛刺现象

为了更快的定位您的问题,请提供以下信息,谢谢
【详述】平时连接查询均在毫秒级别,但不定时出现耗时达到秒级别,影响业务正常查询,但从监控看没看到有什么其它大查询影响,查询日志只看到BE.warn在毛刺的时间段出现大量的 (starrocks-mysql-nio-pool-22611|174202) [Coordinator.endProfile():2602] failed to get profile within 2 seconds 日志,除此外无其它警告或报错日志
【背景】正常查询
【业务影响】
【是否存算分离】否
【StarRocks版本】例如:2.5.21 dc2bcdb
【集群规模】例如:3fe(1 follower+2observer)+3be(fe与be混部)
【机器信息】CPU虚拟核/内存/网卡,例如:32C/128G/万兆
【联系方式】为了在解决问题过程中能及时联系到您获取一些日志信息,请补充下您的联系方式,例如:社区群4-小李或者邮箱,谢谢
【附件】

  • Profile信息,如何获取profile
    由于profile时间过短,而毛刺观测延后,导致无法获取到实际耗时较高的profile
  • 并行度:show variables like ‘%parallel_fragment_exec_instance_num%’;
  • parallel_fragment_exec_instance_num 1
    show variables like ‘%pipeline_dop%’;
  • pipeline_dop 0
    • pipeline是否开启:show variables like ‘%pipeline%’;
      image
    • 执行计划:explain costs + sql
      日常耗时:
      image
PLAN FRAGMENT 0
 OUTPUT EXPRS:23: sum
  PARTITION: UNPARTITIONED

  RESULT SINK

  4:AGGREGATE (merge finalize)
  |  output: sum(23: sum)
  |  group by: 
  |  
  3:EXCHANGE

PLAN FRAGMENT 1
 OUTPUT EXPRS:
  PARTITION: RANDOM

  STREAM DATA SINK
    EXCHANGE ID: 03
    UNPARTITIONED

  2:AGGREGATE (update serialize)
  |  output: sum(20: cash)
  |  group by: 
  |  
  1:Project
  |  <slot 20> : 20: cash
  |  
  0:OlapScanNode
     TABLE: t_app_pub_user_payment_ri
     PREAGGREGATION: OFF. Reason: Aggregate Operator not match: SUM <--> REPLACE
     PREDICATES: 1: gameid = 291, 3: recharge_user = '9_89185540', 2: logtime >= '2024-08-29 18:47:54', 2: logtime <= '2024-09-12 04:00:00'
     partitions=2/63
     rollup: t_app_pub_user_payment_ri
     tabletRatio=30/30
     tabletList=1907671,1907675,1907679,1907683,1907687,1907691,1907695,1907699,1907703,1907707 ...
     cardinality=1
     avgRowSize=30.730707
     numNodes=0

show variables like ‘%enable_profile%’;看下结果,为false表示未开启profile采集,可以set global enable_profile=true,方便的话请提供一个查询耗时的profile。

image
profile是上报的
现在问题是等我们观察到这个现象时,这个耗时过长的profile已经消失了,我们再执行无法复现,正常执行SQL是毫秒级别的

http://leader_fe_ip:8030/query 通过这个命令可以查看最近100个sql,如果有慢查询可以在结果中获取到profile。可以先set global pipeline_dop =4 然后观察下

100个也很快刷没了,SQL很多的,长时间或者单独执行都处于毫秒级别,且FE日志在毛刺时打印了failed to get profile within 2 seconds,还有profile吗,这个是不是profile就没收集到?

这个不是查询的profile,是导入过程中的一个保护性机制

好的,我们写个抓取脚本抓取下看看

这是抓取的一个profile
8847c7de-69d9-11ef-999c-5254002c4bf9_profile.txt (31.4 KB)
没看到具体耗时在哪

先set global pipeline_dop =4 然后观察下

设置了仍旧存在该问题,并且查看p999监控这个还是很频繁的,表是唯一模型

请再提供一个慢查询的profile,单独执行如果耗时很短,请再提供个耗时短的profile

慢查询:
080de735-6a63-11ef-a089-5254005c14fc_profile.txt (31.0 KB)
正常:
normal.txt (33.0 KB)

看配置设置没有生效,查询使用的dop还是0,set global pipeline_dop =4 然后重新连接数据库执行show variables like "pipeline_dop"看下设置的成功不

还有个问题,如果并发60S,2.5版本,还有其它办法抓么,写脚本都没抓到,我们也出现毛刺现象~
之前有个大神回复(长尾上报,这个文档有么)

dop未设置:
bak_0.txt (32.4 KB)
dop设置为4:
ec2ce640-6e71-11ef-999c-5254002c4bf9.profile (31.0 KB)

FE BE 之间连接是不是有问题

连接没问题,这个集群已经运行了很长时间了,之前是2.5.14,最近升级到了2.5.21

从这个profile上看查询消耗时间很少,FE 给 BE发plan看起来卡了一小段时间

这个是在等待?集群内网络应该都是正常的,等待是不是BE有队列之类的参数控制?并且还有个问题就是每次毛刺都是5s左右,这个感觉也是某些参数影响

你搜一下这个query的所有 fragment 下发日志,现象应该是有些 fragment id prepare 时间会相差5s