降本增笑？记一次Doris故障排查

上个月某一天流量晚高峰的时候，Doris 集群突然出现告警，CPU 使用率高于 90%，从七点初到八点多，持续了一个多小时。这是之前没有遇到过的，影响了线上环境直播功能很大一部分的数据查询，算是一次比较严重的事故。当天晚上的集群维护我没有参与，第二天才开始排查故障原因，下面是梳理了整个排查的思路和过程。

在开始之前，先说一下我们的集群情况，版本是 1.2.7，集群是3 FE、3 BE，其中 FE 是 1 个 Follower 和 2 个 Observer，每个 BE 是 16 核 64G。

现象

晚上 19 点 12 分开始，BE 的 CPU 使用率持续爆满

■【腾讯云可观测平台告警】 
您好！您账号（账号ID: xxxxxxx，昵称: 正式环境）的腾讯云可观测平台告警已触发
告警内容: CDWDORIS_BE告警|CPU使用率 > 90%
当前数据: 98.569% (CPU使用率)
告警对象: cdwdoris-bp1xxxx#10.0.xx.xxx
项目|地域: - | 上海
告警策略: doris_be监控
触发时间: 2023-12-06 19:12:00 (UTC+08:00)

下面这张图可以看到，19 点初 CPU 使用率开始上涨，而后其中一台机器（橙色线）直接涨到接近 100%的地方，另外两台的使用率开始逐渐下降。过了一段时间后，刚刚使用率爆满的机器（橙色线）开始下降，另一台（绿色线）BE 开始直线上升，而后两者不断交替上升下降，持续了一个多小时。

下面是同一段时间内（19:00~20:30期间），其他指标的情况，可以看到在 BE 机器 CPU 爆满时，内存使用率、节点接收的流量、机器负载、当前所有 Rowset 个数也相比其他机器高不少。

分析

基于上面的现象做出分析，首先每天晚上流量都会迎来一波高峰，七点初的 CPU 上涨是正常现象，一般会到 80%，不会到90%。不正常的是，之前没有出现过 CPU 被打满的情况，而今天出现了，应该是集群处理的压力比之前大了。这不外乎两种情况，一是写入的数据突增，集群处理不过来；二是查询变多或者有某个大查询，把 CPU 打满了。

下面开始排查问题原因。

排查问题

首先是看写入是否有突增。

从上面可以知道，CPU 被打满的时候 Rowset 数是上升的，而且明显高于其他两台机器，这时可能会认为 Rowset 上涨就是写入的数据量增加，所以是写入把集群打满了。

但其实这么理解有个误区，首先我们要知道 Doris 的 Rowset 代表什么。

Rowset 是数据变化的集合，数据写入导致集合数量上涨，做 Compaction 后集合数量下降，总的集合数就是上涨的量和下降的量之差决定的，因此总的 Rowset 个数的上涨，可能是因为数据写入入太多，也有可能是机器没来得及做合并，所以没法很快的下降。

前面我们知道，此时 CPU 是被打满的，所以也有可能是 CPU 忙不过来，没法做 Compaction 导致总 Rowset 个数上涨。因此并不能从 Rowset 个数的增加就判断是写入引起的故障，还得看数据真实的写入量。

这一点可以从“节点接收流量”指标看，如下图红框部分。可以看到出事这段时间的节点接收流量并不高，跟平时差不多。

当时看了这个指标我们还不放心，还去看了 Kafka 的流量，因为我们大部分的数据是从 Kafka 写到 Doris 的。排查了几个数据量比较大的主题，都没有发现数据突增，跟平时差不多。

到这里基本可以排除写入的影响了，接下来看看查询是否有增加。

查询有两个方面要考虑，一是查询的数量，二是查询的数据量，也就是看是否有大 SQL。

查询的数量方面，可以看“查询请求数量”指标：

从图中可以看到，这段时间内的请求是偏低的，应该是机器 CPU 满了，无法处理更多请求导致的，所以这里看不出什么问题来。

接下来看是否有大 SQL，主要通过 Doris 的审计表看，这里分享排查的语句，主要是找出出事的时间点，查询最慢的 50 个SQL：

select *
from
  doris_audit_tbl__
where
  time >= 'your_start_time'
  and time <= 'your_end_time'
order by
  query_time desc
limit 50;

此外，如果某一个业务比较重要，可以针对这个业务的查询 SQL 给审计表创建一张视图，用于快速分析这个业务的查询情况。比如我们有一个比较重要的直播业务，创建了下面的视图：

CREATE VIEW `doris_audit_view` COMMENT 'VIEW' AS
SELECT substr(`stmt`, instr(`stmt`, 'app_id = ') + 10, 15) AS `app_id`,
  substr(`stmt`, instr(`stmt`, 'alive_id = ') + 12, 26) AS `alive_id`,
  date_format(`time`, '%Y-%m-%d') AS `day`,
  date_format(`time`, '%Y-%m-%d %H') AS `hour`,
  date_format(`time`, '%Y-%m-%d %H:%i') AS `min`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`query_id` AS `query_id`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`time` AS `time`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`client_ip` AS `client_ip`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`user` AS `user`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`db` AS `db`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`state` AS `state`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`query_time` AS `query_time`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`scan_bytes` AS `scan_bytes`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`scan_rows` AS `scan_rows`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`return_rows` AS `return_rows`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`stmt_id` AS `stmt_id`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`is_query` AS `is_query`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`frontend_ip` AS `frontend_ip`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`cpu_time_ms` AS `cpu_time_ms`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`sql_hash` AS `sql_hash`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`peak_memory_bytes` AS `peak_memory_bytes`,
  `default_cluster:doris_audit_db__`.`doris_audit_tbl__`.`stmt` AS `stmt`
FROM `default_cluster:doris_audit_db__`.`doris_audit_tbl__`
WHERE substr(`stmt`, instr(`stmt`, 'app_id = ') + 10, 15) LIKE 'app%';

基于上面的视图表，可以快速找到慢 SQL 对应的直播是哪一个：

select app_id,alive_id,query_time,stmt
from doris_audit_view
where
  time >= 'your_start_time'
  and time <= 'your_end_time'
order by
  query_time desc
limit 50;

这里找出了查询时间最长的 50 条 SQL，然而没有发现什么问题。前 50 中，query_time 最高的 4.993s，最低 4.145s。在集群正常的时候，单独拎出这里面的每个 SQL 来查询，也都能在最多一秒的时间内查完。说明不是某个大 SQL 导致的，集群 CPU 过高导致每个 SQL 都变慢了。

此外，故障期间也有一些执行失败的 SQL，看了一下也没有什么问题，都是正常的业务语句，再次重跑也能正常查询。

到这里似乎陷入的死局，哪哪都正常，谁是压死骆驼的最后一根稻草呢？

还有一个地方可以看，那就是查询的数据量，Doris 的审计表有统计了每个 SQL 扫描的数据大小和行数。

下面是查询语句：

select
  sum(scan_rows),
  count(1),
  sum(scan_rows)/count(1)
from
  doris_audit_tbl__
where
  time >= 'your_start_time'
  and time <= 'your_end_time';

这个 SQL 查询故障期间总的数据扫描量，以及每个 SQL 的平均数据扫描量。将故障期间的结果跟故障前几天同个时间段的结果对比，可以发现这段时间内扫描的数据量是以往的近乎两倍，虽然 SQL 数量少了，但每个 SQL 查询的数据量却大了不少。

12-06 19:08～19:12 3351786511	16753	200070.82379275354
12-05 19h          35273155364	290322	121496.66702488961
12-05 19:08～19:12 2614057068	20180	129537.02021803767

结合上面的集群情况，当时集群的 CPU 和内存都处于比较高的状态，集群的健康状况本就不怎么好，再加上这一波大查询，就导致 CPU 一路狂奔到 100%无法回头。CPU 被打满又会影响 Compaction 任务，导致 Rowset 数量上升，而一旦上升了又需要更多 Compaction 任务、需要更多的 CPU 资源，恶性循环，以此往复。而在此期间写入和查询都没有停止，所以这次故障也是持续了挺长时间。

好在我们是双集群，两套集群互为主备，详细情况可以看这篇文章，所以后面发生这种事情可以通过切集群解决。

解决方案

总结一下这次事故的两个原因：一是集群健康状况不佳，主要体现在机器内存使用率和 CPU 使用率都偏高，内存偏高的原因应该是内存泄漏，但尚不明确，总之我们每隔一段时间都得重启一次 BE，这是一直都有的问题。二是有一波查询数据量比较大的 SQL 过来，成了压死骆驼的最后一根稻草。

所以可以看到，集群已经 Hold 不住这么多的查询了，得扩容 BE 了。此外，也要做好预警，当内存偏高时应该及时重启节点释放内存。

这次事故后，我们增加了两个 BE 节点，并把集群升到 1.2.8 版本，这个版本解决了一些内存泄漏问题。