여러분,
Clickhouse Server 버전: 22.8.21(테스트를 위해 데이터를 복원하기 위해 에서 지원하는 다양한 22.x 및 23.x 버전을 시도했지만 clickhouse-backup쿼리 성능이 향상되지 않은 것 같습니다).
여기 클릭하우스 서버에서 정말 이상한 동작을 발견했습니다(전용 컴퓨터와 동일한 데이터가 로드된 도커 이미지 모두에서).
때로는 쿼리를 완료하는 데 최대 50ms가 걸리고 다른 쿼리는 완료하는 데 250초 이상이 걸립니다(그리고 200초 쿼리를 충분히 자주 실행하면 모든 모양의 캐시에 채워지고 최대 50ms까지 내려갑니다).
데이터 세트는 단순 인덱스가 있는 테이블에 있습니다(쿼리는 기본 인덱스에서 실행되지 않으므로 전체 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';
실행되는 쿼리는 다음과 같습니다. SELECT * FROM cdrs_processed WHERE CorrelationID='<some guid>' ORDER BY Id; GUID마다 쿼리 응답 시간이 다릅니다. 여기서 흥미로운 부분은 다음과 같습니다.
트래픽 전반에 걸쳐 PCAP를 실행하면 성능이 좋은 쿼리(예: 레코드가 ~50ms 내에 반환됨)에서 서버가 먼저 열 헤더로 응답한 다음 데이터로 응답합니다. 읽기 속도가 느려지는 CorrelationID 값을 선택하면 PCAP 트래픽은 연결 및 쿼리를 표시한 다음 전체 TCP KeepAlive 메시지를 표시하고 그런 다음(시간 초과되지 않은 경우) 열 헤더 및 쿼리를 보냅니다. 자료.
배포된 클릭하우스 서버 소프트웨어는 최소한의 쿼리(1-2/초)를 수신하는 AWS EC2 r5a.xlarge 노드에서 실행되고 있으며, 어떤 이상한 이유로 EC2 인스턴스의 4 vCPU를 100% 회전시키고 있습니다. 이 서버에는 백업에서 데이터를 가져와 개발자 시스템에서 clickhouse-server를 실행하는 로컬 도커 이미지로 복원할 때와 동일한 쿼리 성능 문제가 있습니다.
쿼리를 실행하기 전에
clickhouse-client및 실행을 사용하여 쿼리를 디버깅하는 경우 .set send_logs_level='trace';성능이 좋은 쿼리라면 재미있는 로그를 얻습니다.
[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>
모든 것이 괜찮습니다. 쿼리가 느리면 흥미로워집니다. 해당 로그 줄의 첫 번째 줄은 타임스탬프에 따라 인쇄되고 두 번째 및 후속 줄은 쿼리가 완료될 때까지 인쇄되지 않지만 올바른 시간에 게시된 것처럼 타임스탬프를 포함합니다. 즉.
이 줄이 인쇄됩니다.
[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
- 다음으로, server0은 지난 6시간 이상 조용했고 어떤 종류의 쿼리도 없었으며 서버로 전송되는 것은 프로메테우스 메트릭 스크랩뿐입니다. 그러나 추적 로그는 지속적으로 스크롤되고 있습니다.
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
이는 어떤 형태의 쿼리/병합/삽입을 처리하려고 시도하고 있음을 나타냅니다.
6시간 동안 종료된 클라이언트 응용 프로그램은 대부분 초당 1~2개의 요청을 처리합니다. 해당 조합에 업데이트 요청이 있을 수 있지만 대신 삽입으로 교체하고 ReplacingMergeTree동작에 의존할 수 있습니다.
누구든지 변경하거나 조정해야 하는 항목을 어디서/무엇을 찾을지에 대한 아이디어를 제공할 수 있습니까? 이 단계에서는 순차 스캔이 충분히 성능이 좋기 때문에 데이터 전체에 대한 인덱스 부족은 일부 쿼리에서는 문제가 되지 않는 것 같습니다. 우리는 데이터 전반에 걸쳐 필요한 올바른 인덱스/구체화된 뷰/예측을 식별하여 그것이 사물에 어떤 영향을 미치는지 확인할 수 있도록 안정적인 쿼리 성능을 얻으려고 노력하고 있지만 클릭하우스에서는 안정적인 성능을 얻을 수 없기 때문에..)