☰

Непостоянная производительность запросов к базе данных Clickhouse

tag-icon • tag-icon performance database query
Непостоянная производительность запросов к базе данных Clickhouse

Близкие,

Версия сервера Clickhouse: 22.8.21 (пробовал различные версии 22.x и 23.x, поддерживаемые для clickhouse-backupвосстановления моих данных в целях тестирования, ни одна из них не улучшила производительность запросов).

Я обнаружил действительно странное поведение сервера Clickhouse (как на выделенной машине, так и в образе Docker с теми же загруженными данными).

Иногда выполнение запросов занимает около 50 мс, другим требуется более 250 с (а если вы будете запускать запрос длительностью 200 с достаточно часто, то, судя по всему, он попадет в какой-то кэш, и время выполнения сократится до ~50 мс).

Набор данных находится в таблице с простым индексом (запросы не выполняются по основному индексу, поэтому будет сканироваться весь набор данных объемом 3,5 ГБ).


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; Разные руководства имеют разное время ответа на запрос. Интересные части здесь следующие:

  1. Запуск PCAP по всему трафику, при производительном запросе (т. е. записи возвращаются в течение ~50 мс) сервер отвечает сначала заголовками столбцов, а затем данными. Когда выбирается значение CorrelationID, которое приводит к медленному чтению, трафик PCAP показывает соединение и запрос, затем целую кучу сообщений TCP KeepAlive, и только затем (если не истекло время ожидания) он отправляет заголовки столбцов и данные.

  2. Развернутое программное обеспечение clickhouse-server работает на узле AWS EC2 r5a.xlarge, получающем минимальное количество запросов (1-2/сек), и по какой-то странной причине оно нагружает 4 vCPU экземпляра EC2 на 100%. У этого сервера те же проблемы с производительностью запросов, что и при извлечении данных из резервной копии и восстановлении их в локальный образ docker, на котором запущен clickhouse-server в системе разработчиков.

  3. При отладке запроса с использованием 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
  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

что указывает мне на то, что он пытается обработать какую-то форму запросов/слияний/вставок.

Одно клиентское приложение (которое было отключено в течение 6 часов) обрабатывает максимум 1-2 запроса в секунду. В этом миксе может быть запрос на обновление, но я могу заменить его вставкой и положиться на поведение ReplacingMergeTree.

Может ли кто-нибудь дать идеи, где/что искать, чтобы что-то изменить или подправить. Отсутствие индекса по данным, похоже, не является проблемой для некоторых запросов, поскольку последовательное сканирование достаточно производительно на этом этапе. Мы пытаемся получить надежную производительность запросов, чтобы мы могли определить правильные индексы/материализованные представления/проекции, которые нам нужны по данным, чтобы увидеть, как они влияют на вещи, но поскольку мы не можем получить надежную производительность от Clickhouse...).

Связанный контент