超詳細 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 列中列出的設定的值