Các bạn ơi,
Phiên bản Clickhouse Server: 22.8.21 (mình đã thử nhiều phiên bản 22.x và 23.x được clickhouse-backup hỗ trợ để khôi phục dữ liệu và test, nhưng không có phiên bản nào cải thiện được hiệu năng truy vấn).
Mình đang gặp một số hiện tượng khá lạ với server Clickhouse này (cả trên máy riêng và trên docker image với dữ liệu giống nhau).
Đôi khi truy vấn chỉ mất ~50ms để hoàn thành, nhưng đôi khi lại mất đến hơn 250s (và nếu bạn chạy truy vấn 200s đủ nhiều lần, nó sẽ được lưu vào cache và thời gian giảm xuống còn ~50ms).
Bộ dữ liệu nằm trong một bảng với index đơn giản (các truy vấn không chạy trên primary index nên nó sẽ quét toàn bộ bộ dữ liệu 3.5Gb).
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’;
Truy vấn đang chạy là SELECT * FROM cdrs_processed WHERE CorrelationID='<some guid>’ ORDER BY Id; . Các CorrelationID khác nhau cho thời gian trả lời truy vấn khác nhau. Những điểm thú vị ở đây là:
-
Khi chạy PCAP trên traffic, với truy vấn hiệu năng cao (tức là records được trả về trong ~50ms), server trả lời trước với header cột và sau đó là dữ liệu. Khi chọn một giá trị CorrelationID dẫn đến đọc chậm, traffic PCAP cho thấy connection và query, sau đó là một loạt các tin nhắn TCP KeepAlive, và chỉ sau đó (nếu không timeout) nó mới gửi header cột và dữ liệu.
-
Phần mềm clickhouse-server được triển khai đang chạy trên node AWS EC2 r5a.xlarge, nhận được ít truy vấn (1-2/giây), và nó đang chạy 4 vCPU của instance EC2 ở mức 100% vì một lý do nào đó rất kỳ lạ. Server này có vấn đề về hiệu năng truy vấn tương tự như khi chúng ta lấy dữ liệu từ bản sao lưu và khôi phục nó vào một docker image cục bộ chạy clickhouse-server trên hệ thống của developer.
-
Khi debug truy vấn bằng clickhouse-client và chạy set send_logs_level=’trace’; trước khi chạy truy vấn. Nếu đó là một truy vấn hiệu năng cao, chúng ta sẽ nhận được các log vui vẻ như sau:
[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>
và mọi thứ đều ổn. Nếu đó là một truy vấn chậm, thì nó trở nên thú vị. Dòng đầu tiên của dòng log đó được in ra với timestamp, các dòng thứ hai và các dòng tiếp theo không được in ra cho đến khi truy vấn hoàn thành, nhưng chứa timestamp như thể chúng được xuất bản đúng lúc. Ví dụ:
Dòng này được in ra.
[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)
Sau đó chúng ta không nhận được gì cho đến 2023.09.06 05:31:35.309735 , khi đó chúng ta nhận được tất cả các dòng trace còn lại được in ra như những dòng bên dưới. (Mình đã quay video về điều này).
[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
4. Tiếp theo, server0 đã im lặng trong hơn 6 giờ qua, không có truy vấn nào được gửi đến nó, chỉ có các prometheus metrics scrapes được gửi đến nó. Tuy nhiên, các log trace liên tục cuộn qua với
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
cho thấy rằng nó đang cố gắng xử lý một số dạng truy vấn/merge/insert.
Ứng dụng client duy nhất (đã tắt trong 6 giờ) xử lý tối đa 1-2 request/giây. Có thể có một request cập nhật trong đó, nhưng mình có thể thay thế chúng bằng insert và dựa vào hành vi ReplacingMergeTree .
Có ai có thể đưa ra ý tưởng về nơi/thứ cần tìm để thay đổi hoặc tinh chỉnh không? Việc thiếu index trên dữ liệu dường như không phải là vấn đề đối với một số truy vấn vì việc quét tuần tự đủ hiệu quả ở giai đoạn này. Chúng ta đang cố gắng để có được hiệu năng truy vấn đáng tin cậy để có thể xác định các index/materialized views/projections chính xác mà chúng ta cần trên dữ liệu để xem chúng ảnh hưởng như thế nào, nhưng vì chúng ta không thể có được hiệu năng đáng tin cậy từ Clickhouse…).
(cũng đã đăng lên: https://serverfault.com/questions/1143170/inconsistent-clickhouse-database-query-performance))
