☰

Desempenho inconsistente de consulta ao banco de dados Clickhouse

tag-icon • tag-icon performance database query
Desempenho inconsistente de consulta ao banco de dados Clickhouse

Pessoas,

Versão do Clickhouse Server: 22.8.21 (tentei uma variedade de versões 22.xe 23.x suportadas por clickhouse-backuppara restaurar meus dados para teste, nenhuma pareceu melhorar o desempenho da consulta).

Estou encontrando um comportamento realmente estranho com um servidor clickhouse aqui (tanto em uma máquina dedicada quanto em uma imagem docker com os mesmos dados carregados).

Às vezes, as consultas levam aproximadamente 50 ms para serem concluídas, outras levam mais de 250 segundos para serem concluídas (e se você executar a consulta 200 com frequência suficiente, ela será preenchida em algum cache de todas as aparências e cairá para aproximadamente 50 ms).

O conjunto de dados está em uma tabela com um índice simples (as consultas não estão sendo executadas no índice primário, portanto, ele verificará todo o conjunto de dados de 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';

A consulta que está sendo executada é esta. SELECT * FROM cdrs_processed WHERE CorrelationID='<some guid>' ORDER BY Id; Guias diferentes têm tempos de resposta de consulta diferentes. As partes interessantes aqui são estas:

  1. Executando um PCAP no tráfego, em uma consulta de alto desempenho (ou seja, os registros são retornados em aproximadamente 50 ms), o servidor responde primeiro com os cabeçalhos das colunas e depois com os dados. Quando um valor CorrelationID é selecionado que resulta em uma leitura lenta, o tráfego PCAP mostra a conexão e a consulta, depois um monte de mensagens TCP KeepAlive, e só então (se não tiver atingido o tempo limite) ele envia os cabeçalhos das colunas e os dados.

  2. O software clickhouse-server implantado está sendo executado em um nó AWS EC2 r5a.xlarge recebendo consultas mínimas (1-2/segundo) e está girando as 4 vCPUs da instância EC2 em 100% por algum motivo bizarro. Este servidor tem os mesmos problemas de desempenho de consulta de quando pegamos os dados de um backup e os restauramos em uma imagem docker local executando clickhouse-server em um sistema de desenvolvedores.

  3. Ao depurar a consulta usando clickhouse-cliente executando set send_logs_level='trace';antes de executar a consulta. Se for uma consulta de alto desempenho, obteremos os registros divertidos.

[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>

e está tudo bem, se for uma consulta lenta fica interessante. A primeira linha dessa linha de log é impressa de acordo com o carimbo de data/hora, a segunda e as linhas subsequentes não são impressas até que a consulta seja concluída, mas contêm o carimbo de data/hora como se tivessem sido publicadas no momento correto. ou seja.

Esta linha é impressa.

[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)

Então não obtemos nada até 2023.09.06 05:31:35.309735obtermos todo o resto das linhas de rastreamento impressas, como as abaixo. (Eu gravei um vídeo disso acontecendo).

[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. Em seguida, o server0 ficou quieto nas últimas 6 horas, não houve nenhuma consulta de qualquer tipo, a única coisa que foi enviada a ele foram raspagens de métricas do Prometheus. No entanto, os logs de rastreamento estão constantemente passando com
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

o que me indica que ele está tentando processar alguma forma de consultas/mesclagem/inserções.

O único aplicativo cliente (que foi desligado por 6 horas) processa no máximo 1 a 2 solicitações/segundo. Pode haver uma solicitação de atualização nesse mix, mas posso substituí-la por uma inserção e confiar no ReplacingMergeTreecomportamento.

Alguém pode fornecer idéias sobre onde/o que procurar por algo que precisa ser alterado ou ajustado. A falta de índice nos dados não parece ser um problema para algumas das consultas, uma vez que a verificação sequencial tem desempenho suficiente neste estágio. Estamos tentando obter um desempenho de consulta confiável para que possamos identificar os índices/visualizações/projeções materializadas corretas que precisamos nos dados para ver como eles afetam as coisas, mas como não podemos obter um desempenho confiável do clickhouse..).

informação relacionada