☰

Clickhouse データベース クエリのパフォーマンスが一貫していない

tag-icon • tag-icon performance database query
Clickhouse データベース クエリのパフォーマンスが一貫していない

皆さん、

Clickhouse Server バージョン: 22.8.21 (テストのためにデータを復元するために、サポートされているさまざまな 22.x および 23.x バージョンを試しましたがclickhouse-backup、クエリ パフォーマンスが向上したようには見えませんでした)。

ここで、クリックハウス サーバーで非常に奇妙な動作が見つかりました (専用マシンと、同じデータがロードされた Docker イメージの両方)。

クエリが完了するまでに約 50 ミリ秒かかる場合もあれば、完了するまでに 250 秒以上かかる場合もあります (200 秒のクエリを頻繁に実行すると、どうやらキャッシュに取り込まれ、約 50 ミリ秒まで短縮されるようです)。

データ セットは、単純なインデックスを持つテーブル内にあります (クエリはプライマリ インデックス全体で実行されないため、3.5 Gb のデータ セット全体がスキャンされます)。


CREATE TABLE `cdrs_processed` (
    `Id` UInt64,
    `Direction` String,
    `Time` DateTime('UTC'),
    `CallID` String,
    `CorrelationID` String,
... <snip> ...
)  
ENGINE = ReplacingMergeTree(Id)  
PARTITION BY toYYYYMM(Time)  
ORDER BY (Id,Time)  
PRIMARY KEY Id  
SETTINGS index\_granularity = 8192  
COMMENT 'Processed and enriched CDR records';

実行されているクエリはこれです。GUIDSELECT * FROM cdrs_processed WHERE CorrelationID='<some guid>' ORDER BY Id; によってクエリの応答時間が異なります。ここで興味深い部分は次のとおりです。

  1. トラフィック全体で PCAP を実行すると、パフォーマンスの高いクエリ (つまり、レコードが約 50 ミリ秒で返される) でサーバーは最初に列ヘッダーで応答し、次にデータで応答します。読み取り速度が遅くなる CorrelationID 値が選択されると、PCAP トラフィックは接続とクエリを表示し、次に大量の TCP KeepAlive メッセージを表示し、その後 (タイムアウトしなかった場合) のみ列ヘッダーとデータを送信します。

  2. デプロイされた clickhouse-server ソフトウェアは、最小限のクエリ (1 ～ 2/秒) を受信する AWS EC2 r5a.xlarge ノードで実行されており、何らかの奇妙な理由で EC2 インスタンスの 4 つの vCPU を 100% で回転させています。このサーバーには、バックアップからデータを取得して、開発者システムで clickhouse-server を実行しているローカル Docker イメージに復元する場合と同じクエリ パフォーマンスの問題があります。

  3. clickhouse-clientクエリを実行する前に、と を使用してクエリをデバッグする場合set send_logs_level='trace';。パフォーマンスの高いクエリの場合は、 の fun ログが取得されます。

[2f7418aeaf9c] 2023.09.06 05:28:27.307306 [ 287 ] {5c35e3ba-15d3-494e-991b-9a93674ae9af} <Debug> executeQuery: (from 172.28.0.1:47140) SELECT * FROM nextvoice.cdrs_processed WHERE CorrelationID='E3065F87-3CB9-4C58-A12D-66A686B8C53D'; (stage: Complete)
[2f7418aeaf9c] 2023.09.06 05:28:27.322028 [ 287 ] {5c35e3ba-15d3-494e-991b-9a93674ae9af} <Debug> InterpreterSelectQuery: MergeTreeWhereOptimizer: condition "CorrelationID = 'E3065F87-3CB9-4C58-A12D-66A686B8C53D'" moved to PREWHERE
[2f7418aeaf9c] 2023.09.06 05:28:27.328348 [ 287 ] {5c35e3ba-15d3-494e-991b-9a93674ae9af} <Debug> InterpreterSelectQuery: MergeTreeWhereOptimizer: condition "CorrelationID = 'E3065F87-3CB9-4C58-A12D-66A686B8C53D'" moved to PREWHERE
[2f7418aeaf9c] 2023.09.06 05:28:27.331671 [ 287 ] {5c35e3ba-15d3-494e-991b-9a93674ae9af} <Trace> ContextAccess (default): Access granted: SELECT(Id, Direction, Time, CallID, .... <snip>

すべてが順調に進んでいますが、クエリが遅い場合は興味深いことになります。ログ行の最初の行はタイムスタンプに従って印刷され、2 行目以降はクエリが完了するまで印刷されませんが、正しい時間に発行されたかのようにタイムスタンプが含まれます。つまり、

この行は印刷されます。

[2f7418aeaf9c] 2023.09.06 05:30:06.838300 [ 287 ] {f9d77d15-8b7b-42d7-a344-eb0ad09ee690} <Debug> executeQuery: (from 172.28.0.1:47140) SELECT * FROM nextvoice.cdrs_processed WHERE CorrelationID='03FBC351-48A1-4E3A-8257-AA97ED75F7A5'; (stage: Complete)

2023.09.06 05:31:35.309735その後、下図のような残りのトレース ラインがすべて印刷されるまで、何も表示されません(この様子をビデオに撮りました)。

[2f7418aeaf9c] 2023.09.06 05:30:06.860733 [ 287 ] {f9d77d15-8b7b-42d7-a344-eb0ad09ee690} <Trace> InterpreterSelectQuery: FetchColumns -> Complete
[2f7418aeaf9c] 2023.09.06 05:30:06.864526 [ 287 ] {f9d77d15-8b7b-42d7-a344-eb0ad09ee690} <Debug> nextvoice.cdrs_processed (c8be24d5-22dd-4344-a9bf-10db9eabc46d) (SelectExecutor): Key condition: unknown
[2f7418aeaf9c] 2023.09.06 05:30:06.865117 [ 287 ] {f9d77d15-8b7b-42d7-a344-eb0ad09ee690} <Debug> nextvoice.cdrs_processed (c8be24d5-22dd-4344-a9bf-10db9eabc46d) (SelectExecutor): MinMax index condition: unknown
[2f7418aeaf9c] 2023.09.06 05:30:06.880895 [ 287 ] {f9d77d15-8b7b-42d7-a344-eb0ad09ee690} <Debug> nextvoice.cdrs_processed (c8be24d5-22dd-4344-a9bf-10db9eabc46d) (SelectExecutor): Selected 62/62 parts by partition key, 62 parts by primary key, 1873/1873 marks by primary key, 1873 marks to read from 62 ranges
[2f7418aeaf9c] 2023.09.06 05:31:35.309735 [ 287 ] {f9d77d15-8b7b-42d7-a344-eb0ad09ee690} <Debug> nextvoice.cdrs_processed (c8be24d5-22dd-4344-a9bf-10db9eabc46d) (SelectExecutor): Reading approx. 3852688 rows with 4 streams
  1. 次に、server0は過去6時間以上静かで、いかなる種類のクエリも行われておらず、送信されているのはPrometheusメトリックスクレイプのみです。しかし、トレースログは常にスクロールして表示されます。
2023.09.06 10:51:06.000598 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Debug> MergeTask::PrepareStage: Merging 2 parts: from 202309_75514_76920_1105 to 202309_76921_76921_0 into Wide
2023.09.06 10:51:06.000762 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Debug> MergeTask::PrepareStage: Selected MergeAlgorithm: Horizontal
2023.09.06 10:51:06.000789 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Debug> MergeTreeSequentialSource: Reading 10 marks from part 202309_75514_76920_1105, total 70966 rows starting from the beginning of the part
2023.09.06 10:51:06.000924 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Debug> MergeTreeSequentialSource: Reading 2 marks from part 202309_76921_76921_0, total 34 rows starting from the beginning of the part
2023.09.06 10:51:06.029025 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Debug> MergeTask::MergeProjectionsStage: Merge sorted 71000 rows, containing 10 columns (10 merged, 0 gathered) in 0.028416545 sec., 2498544.4219203987 rows/sec., 805.83 MiB/sec.
2023.09.06 10:51:06.030461 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Trace> MergedBlockOutputStream: filled checksums 202309_75514_76921_1106 (state Temporary)
2023.09.06 10:51:06.030766 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Trace> system.trace_log (b09755a5-5004-4d4e-adef-82f4b86b4962): Renaming temporary part tmp_merge_202309_75514_76921_1106 to 202309_75514_76921_1106.
2023.09.06 10:51:06.030821 [ 317 ] {b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106} <Trace> system.trace_log (b09755a5-5004-4d4e-adef-82f4b86b4962) (MergerMutator): Merged 2 parts: from 202309_75514_76920_1105 to 202309_76921_76921_0
2023.09.06 10:51:06.030869 [ 317 ] {} <Debug> MemoryTracker: Peak memory usage to apply mutate/merge in b09755a5-5004-4d4e-adef-82f4b86b4962::202309_75514_76921_1106: 43.34 MiB.
2023.09.06 10:51:07.000655 [ 335 ] {} <Trace> AsynchronousMetrics: MemoryTracking: was 804.53 MiB, peak 3.11 GiB, will set to 807.54 MiB (RSS), difference: 3.01 MiB
2023.09.06 10:51:07.593604 [ 349 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushing system log, 2030 entries to flush up to offset 5643012
2023.09.06 10:51:07.594682 [ 349 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 41.29 GiB.
2023.09.06 10:51:07.595125 [ 349 ] {} <Trace> MergedBlockOutputStream: filled checksums 202309_2778_2778_0 (state Temporary)
2023.09.06 10:51:07.595304 [ 349 ] {} <Trace> system.asynchronous_metric_log (65e48ced-63b1-49f3-b373-fe52139c8fd6): Renaming temporary part tmp_insert_202309_2778_2778_0 to 202309_64623_64623_0.
2023.09.06 10:51:07.595444 [ 349 ] {} <Trace> SystemLog (system.asynchronous_metric_log): Flushed system log up to offset 5643012
2023.09.06 10:51:07.769264 [ 327 ] {} <Trace> system.trace_log (b09755a5-5004-4d4e-adef-82f4b86b4962): Found 2 old parts to remove.
2023.09.06 10:51:07.769291 [ 327 ] {} <Debug> system.trace_log (b09755a5-5004-4d4e-adef-82f4b86b4962): Removing part from filesystem 202309_75514_76856_1041
2023.09.06 10:51:07.769959 [ 327 ] {} <Debug> system.trace_log (b09755a5-5004-4d4e-adef-82f4b86b4962): Removing part from filesystem 202309_76857_76857_0
2023.09.06 10:51:10.302387 [ 475 ] {} <Debug> DNSResolver: Updating DNS cache
2023.09.06 10:51:10.302543 [ 475 ] {} <Debug> DNSResolver: Updated DNS cache
2023.09.06 10:51:10.924813 [ 350 ] {} <Trace> SystemLog (system.metric_log): Flushing system log, 7 entries to flush up to offset 19458
2023.09.06 10:51:10.932845 [ 350 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 41.29 GiB.
2023.09.06 10:51:10.935552 [ 350 ] {} <Trace> MergedBlockOutputStream: filled checksums 202309_2590_2590_0 (state Temporary)
2023.09.06 10:51:10.935969 [ 350 ] {} <Trace> system.metric_log (8c45d18c-4f03-43de-9848-28490ac69588): Renaming temporary part tmp_insert_202309_2590_2590_0 to 202309_60226_60226_0.
2023.09.06 10:51:10.936121 [ 471 ] {} <Debug> system.metric_log (8c45d18c-4f03-43de-9848-28490ac69588) (MergerMutator): Selected 6 parts from 202309_59866_60221_71 to 202309_60226_60226_0
2023.09.06 10:51:10.936149 [ 471 ] {} <Debug> DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 41.29 GiB.
2023.09.06 10:51:10.936234 [ 302 ] {8c45d18c-4f03-43de-9848-28490ac69588::202309_59866_60226_72} <Debug> MergeTask::PrepareStage: Merging 6 parts: from 202309_59866_60221_71 to 202309_60226_60226_0 into Compact

これは、何らかの形式のクエリ/マージ/挿入を処理しようとしていることを示しています。

1 つのクライアント アプリケーション (6 時間シャットダウンされている) は、最大で 1 秒あたり 1 ～ 2 件のリクエストを処理します。その中に更新リクエストが含まれている可能性もありますが、それらを挿入に置き換えて、ReplacingMergeTree動作に頼ることができます。

変更や調整が必要な箇所や内容について、誰かアイデアをいただけませんか。データ全体にインデックスがなくても、この段階ではシーケンシャル スキャンのパフォーマンスが十分であるため、一部のクエリでは問題にならないようです。データ全体に必要な正しいインデックス/マテリアライズド ビュー/投影を特定して、それらがどのように影響するかを確認できるように、信頼性の高いクエリ パフォーマンスを実現しようとしていますが、Clickhouse からは信頼性の高いパフォーマンスが得られないためです。

関連情報