超详细 Clickhouse 负载过高问题快速排查思路教程

语言: CN / TW / HK

时间 2022-10-11 23:02:45 云智慧AIOps社区

主题:

机器配置

Clickhouse 配置内存大小: 250G

Zookeeper 配置内存大小：24G

发现问题

企业相关开发人员通过Grafana监控Clickhouse指标观察到，从12点左右出现了大量的碎片写入，从而引起了相关指标的快速上升。查看云智慧的数字化运维数据平台 DODB （以下简称DODB）概览页也未查看出异常出现源头，而当查看服务器负载情况时，已经上升至900+。

开始排查

检查是否为执行 SQL 太多

当遇到此类问题时，普遍情况下均会猜测是 SQL 执行太多导致。因此，团队开发人员检查了 Clickhouse 的 Process表，以此判断运行中的 SQL 是否过多。与此同时与算法部门的同事进行沟通，最终确认是通过 DODB 写入数据的。随后又查询了一下执行中的 SOL，发现两台机器上运行中的 SOL 不太均衡。

查询 Clickhouse 日志

当查看 Clickhouse 日志时，看到有很多 warn 的日志，但并没有出现有价值的日志。

查询 Zookeeper 日志

当查看 Zookeeper 日志时，发现数据同步有比较大的延迟，超过了1-2s。

排查同步数据延迟是因为需要判断是 load 值上来导致延迟还是因为延迟导致的 load 值上来。可能是一个大查询导致 load 值上来后，引起 Zookeeper 出现问题，从而导致数据无法同步出现数据堆积的情况。因此，在此时查看了监控的读写情况，是由于load值上来后导致写入变慢。

SQL 语句查询

在 Clickhouse 中，所有被执行 Query 均会记录到system.query_log表中。因此可通过该表监控集群的查询情况。以下列举几种用于监控的常用SQL。

最近查询

SELECT   
    event_time,   
    user,   
    query_id AS query,   
    read_rows,   
    read_bytes,   
    result_rows,   
    result_bytes,   
    memory_usage,   
    exception  
FROM clusterAllReplicas('cluster_name', system, query_log)  
WHERE (event_date = today()) AND (event_time >= (now() - 60)) AND (is_initial_query = 1) AND (query NOT LIKE 'INSERT INTO%')  
ORDER BY event_time DESC  
LIMIT 100

慢查询

SELECT   
    event_time,   
    user,   
    query_id AS query,   
    read_rows,   
    read_bytes,   
    result_rows,   
    result_bytes,   
    memory_usage,   
    exception  
FROM clusterAllReplicas('cluster_name', system, query_log)  
WHERE (event_date = yesterday()) AND query_duration_ms > 30000 AND (is_initial_query = 1) AND (query NOT LIKE 'INSERT INTO%')  
ORDER BY query_duration_ms desc  
LIMIT 100

Top10大表

SELECT   
    database,   
    table,   
    sum(bytes_on_disk) AS bytes_on_disk  
FROM clusterAllReplicas('cluster_name', system, parts)  
WHERE active AND (database != 'system')  
GROUP BY   
    database,   
    table  
ORDER BY bytes_on_disk DESC  
LIMIT 10

Top10查询用户

SELECT   
    user,   
    count(1) AS query_times,   
    sum(read_bytes) AS query_bytes,   
    sum(read_rows) AS query_rows  
FROM clusterAllReplicas('cluster_name', system, query_log)  
WHERE (event_date = yesterday()) AND (is_initial_query = 1) AND (query NOT LIKE 'INSERT INTO%')  
GROUP BY user  
ORDER BY query_times DESC  
LIMIT 10

使用慢查询的 SQL 查询

查询结果出来，查看所执行 SQL 具体情况，发现很多都是“异常容器”的。

下图为作战地图所查大屏表，且为 left JOIN 表。由于 life 的 JOIN 在网络及其他因素条件有要求，因此比刚才查询更消耗资源。随后通过时间段查询判断出现异常时间是否匹配，对比发现时间上有些差异。

查询 SQL 查询次数，判断哪次查询 时间 最长以及查询的平均时长。

select left(query, 100) as sql, count() as queryNum, sum(query_duration_ms) as totalTime, totalTime/queryNum as avgTime from system.query_log ql where event_time > toDateTime("2022-09-23 12:00:00") and event_time < toDateTime("2022-09-23 17:00:00") group by sql order by queryNum desc limit 10

通过该 SQL 查询，发现 5 个小时 SQL 查询了将近 4 万次，且同类型查询执行次数均较高，平均执行时间也比较长。此外，也有许多 5 个小时执行两三千次的 SQL 查询，该类查询平均每次耗时均在二三十秒。

查询不包含insert into语句的5个小时查询次数超过1000次的 SQL

select * from (select LEFT(query, 100) as sql, count() as quneryNum, sum(query_duration_ms) as totalTime, totalTime/queryNum as avgTime from system.query_log ql where event_time > toDateTime('2022-09-23 12:00:00') and event_time < toDateTime('2022-09-23 17:00:00') and query not like '%INSERT INTO%' group by sql order by avgTime desc) where queryNum > 1000 limit 50

由于上述 SQL 均做了截取，故需根据所查询 SQL 进一步匹配 SQL。

select query from system.query_log where event_time > toDateTime('2022-09-23 12:00:00') and event_time < toDateTime('2022-09-23 17:00:00') and query like '%需要匹配的sql查询%' limit 5;

使用第三条 SQL 用 queryNum 排序，查询出执行次数多且平均耗时比较大的 SQL，随后定位 SQL。以第二条记录为例：5个小时查询了 38000+次，耗时12s，每分钟查 120+次。

使用第三条 SQL ，将时间 范围改到上午8点到上午12查询。 查询结果对比发现，执行耗时在上午时均很短，但到中午12点以后就变的非常慢了。

由于之前查询发现有部分 left JOIN 的查询，故查询了“异常容器”的left JOIN 的查询,，随后将读取条数为0的排除掉。

select * from (select LEFT(query, 100) as sql, count() as quneryNum, sum(query_duration_ms) as totalTime, totalTime/queryNum as avgTime from system.query_log ql where sql like '%异常容器%' and read_rows != 0 and event_time > toDateTime('2022-09-23 12:00:00') and event_time < toDateTime('2022-09-23 17:00:00') and query not like '%INSERT INTO%' group by sql order by queryNum desc)

根据小时 聚合 每个小时/分钟段查询次数耗时

--按照每小时聚合
select toHour(event_time) as t, count() as queryNum, sum(query_duration_ms) as totalTime, totalTime/queryNum as avgTime from system.query_log ql where event_time > toDateTime('2022-09-23 08:00:00') and event_time < toDateTime('2022-09-23 17:00:00') and query not like '%INSERT INTO%' and query like '%异常容器%' and read_rows != 0 group by t limit 50
--按照每分钟聚合
select toMinute(event_time) as t, count() as queryNum, sum(query_duration_ms) as totalTime, totalTime/queryNum as avgTime from system.query_log ql where event_time > toDateTime('2022-09-23 12:00:00') and event_time < toDateTime('2022-09-23 13:00:00') and query not like '%INSERT INTO%' and query like '%异常容器%' and read_rows != 0 group by t limit 50

查询结果如下：10点开始有，12 点查询响应时间翻了10倍。

从32s开始，响应时间变为24s多，后面的时间也逐渐变长。

查询 left JOIN 的查询个数。

select * from (select LEFT(query, 100) as sql, count() as quneryNum, sum(query_duration_ms) as totalTime, totalTime/queryNum as avgTime from system.query_log ql where query like '% JOIN%' and read_rows != 0 and event_time > toDateTime('2022-09-23 12:00:00') and event_time < toDateTime('2022-09-23 21:00:00') and query not like '%INSERT INTO%' group by sql order by queryNum desc)

发现有问题的表时，查询该表结构。

show create table "shard_2"."cw_db_zabbix_metric_data01_replica"

经查询发现该表创建的比较差，order by 仅有一个 UUID。且该表 JOIN 的 SQL 也比较多，每次查询的读取的条数也特别大。

停掉 SQL ，观察结果

通过观察，发现有不少类似的 JOIN 的 SQL。当停掉一个异常容器指标的 SQL 时会发现 load 值有些许变化，偶尔会降到700多。由于指标管理都是通过 gatewayAPI 调用，停掉 SQL 最快的方法便是直接将 gatewayAPI 停掉，这样只会影响指标 SQL 调，不会影响其他功能使用。将 gatewayAPI 停掉后就不会出现指标调用 SQL 也全部停掉，此时发现 load 值已降低

总结

遇到此类问题可先查看日志，首先在（Clickhouse 日志 Zookeeper 日志）日志中看能否找到有用的信息，例如直接报错信息等，如果在日志中找不到太多有用的信息的话，可以从下面入手。

一般遇到 load 值比较高的情况时，基本上都是发生在查询上面。当遇到这种问题时可先查询带有JOIN 的 SQL 语句是不是很多。随后通过 query_log 表中的一些字段去查询重要信息，通过对字段使用一些函数来获取有用的信息，如获取查询的 SQL，SQL 执行次数、执行时间等。

本次排查过程主要使用query_log表，下面为重要字段：

event_time — 查询开始时间.

query_duration_ms — 查询消耗的时间（毫秒）.

read_rows— 从参与了查询的所有表和表函数读取的总行数.

query — 查询语句.

Clickhouse query_log 表中所有字段

type (Enum8) — 执行查询时的事件类型. 值:
- 'QueryStart' = 1 — 查询成功启动.
- 'QueryFinish' = 2 — 查询成功完成.
- 'ExceptionBeforeStart' = 3 — 查询执行前有异常.
- 'ExceptionWhileProcessing' = 4 — 查询执行期间有异常.
event_date (Date) — 查询开始日期.
event_time (DateTime) — 查询开始时间.
event_time_microseconds (DateTime64) — 查询开始时间（毫秒精度）.
query_start_time (DateTime) — 查询执行的开始时间.
query_start_time_microseconds (DateTime64) — 查询执行的开始时间（毫秒精度）.
query_duration_ms (UInt64) — 查询消耗的时间（毫秒）.
read_rows (UInt64) — 从参与了查询的所有表和表函数读取的总行数. 包括：普通的子查询, IN 和 **JOIN**的子查询. 对于分布式查询 read_rows 包括在所有副本上读取的行总数。每个副本发送它的 read_rows 值，并且查询的服务器-发起方汇总所有接收到的和本地的值。缓存卷不会影响此值。
read_bytes (UInt64) — 从参与了查询的所有表和表函数读取的总字节数. 包括：普通的子查询, IN 和 **JOIN**的子查询. 对于分布式查询 read_bytes 包括在所有副本上读取的字节总数。每个副本发送它的 read_bytes 值，并且查询的服务器-发起方汇总所有接收到的和本地的值。缓存卷不会影响此值。
written_rows (UInt64) — 对于 INSERT 查询，为写入的行数。对于其他查询，值为0。
written_bytes (UInt64) — 对于 INSERT 查询时，为写入的字节数。对于其他查询，值为0。
result_rows (UInt64) — SELECT 查询结果的行数，或**INSERT** 的行数。
result_bytes (UInt64) — 存储查询结果的RAM量.
memory_usage (UInt64) — 查询使用的内存.
query (String) — 查询语句.
exception (String) — 异常信息.
exception_code (Int32) — 异常码.
stack_trace (String) — Stack Trace. 如果查询成功完成，则为空字符串。
is_initial_query (UInt8) — 查询类型. 可能的值:
- 1 — 客户端发起的查询.
- 0 — 由另一个查询发起的，作为分布式查询的一部分.
user (String) — 发起查询的用户.
query_id (String) — 查询ID.
address (IPv6) — 发起查询的客户端IP地址.
port (UInt16) — 发起查询的客户端端口.
initial_user (String) — 初始查询的用户名（用于分布式查询执行）.
initial_query_id (String) — 运行初始查询的ID（用于分布式查询执行）.
initial_address (IPv6) — 运行父查询的IP地址.
initial_port (UInt16) — 发起父查询的客户端端口.
interface (UInt8) — 发起查询的接口. 可能的值:
- 1 — TCP.
- 2 — HTTP.
os_user (String) — 运行 clickhouse-client的操作系统用户名.
client_hostname (String) — 运行clickhouse-client 或其他TCP客户端的机器的主机名。
client_name (String) — clickhouse-client 或其他TCP客户端的名称。
client_revision (UInt32) — clickhouse-client 或其他TCP客户端的Revision。
client_version_major (UInt32) — clickhouse-client 或其他TCP客户端的Major version。
client_version_minor (UInt32) — clickhouse-client 或其他TCP客户端的Minor version。
client_version_patch (UInt32) — clickhouse-client 或其他TCP客户端的Patch component。
http_method (UInt8) — 发起查询的HTTP方法. 可能值:
- 0 — TCP接口的查询.
- 1 — GET
- 2 — POST
http_user_agent (String) — The UserAgent The UserAgent header passed in the HTTP request。
quota_key (String) — 在quotas 配置里设置的“quota key” （见 keyed).
revision (UInt32) — ClickHouse revision.
ProfileEvents (Map(String, UInt64))) — Counters that measure different metrics. The description of them could be found in the table 系统。活动
Settings (Map(String, String)) — Names of settings that were changed when the client ran the query. To enable logging changes to settings, set the log_query_settings 参数为1。
thread_ids (Array(UInt64)) — 参与查询的线程数.
Settings.Names (Array（String)) — 客户端运行查询时更改的设置的名称。要启用对设置的日志记录更改，请将log_query_settings参数设置为1。
Settings.Values (Array（String)) — Settings.Names 列中列出的设置的值