机器配置
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) — TheUserAgent
The UserAgent header passed in the HTTP request。 -
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 thelog_query_settings
参数为1。 -
thread_ids
(Array(UInt64)) — 参与查询的线程数. -
Settings.Names
(Array(String)) — 客户端运行查询时更改的设置的名称。 要启用对设置的日志记录更改,请将log_query_settings参数设置为1。 -
Settings.Values
(Array(String)) —Settings.Names
列中列出的设置的值
开源项目推荐
云智慧已开源数据可视化编排平台 FlyFish 。通过配置数据模型为用户提供上百种可视化图形组件,零编码即可实现符合自己业务需求的炫酷可视化大屏。 同时,飞鱼也提供了灵活的拓展能力,支持组件开发、自定义函数与全局事件等配置, 面向复杂需求场景能够保证高效开发与交付。
如果喜欢我们的项目,请不要忘记点击下方代码仓库地址,在 GitHub / Gitee 仓库上点个 Star,我们需要您的鼓励与支持。此外,即刻参与 FlyFish 项目贡献成为 FlyFish Contributor 的同时更有万元现金等你来拿。
GitHub 地址: https://github.com/CloudWise-OpenSource/FlyFish
Gitee 地址: https://gitee.com/CloudWise/fly-fish
微信扫描识别下方二维码,备注【飞鱼】加入AIOps社区飞鱼开发者交流群,与 FlyFish 项目 PMC 面对面交流~