☰

Inkonsistente Leistung der Clickhouse-Datenbankabfragen

tag-icon • tag-icon performance database query
Inkonsistente Leistung der Clickhouse-Datenbankabfragen

Leute,

Clickhouse-Serverversion: 22.8.21 (habe verschiedene von unterstützte 22.x- und 23.x-Versionen ausprobiert, um clickhouse-backupmeine Daten zu Testzwecken wiederherzustellen, keine schien die Abfrageleistung zu verbessern).

Ich stelle hier bei einem Clickhouse-Server ein wirklich merkwürdiges Verhalten fest (sowohl auf einer dedizierten Maschine als auch auf einem Docker-Image mit denselben geladenen Daten).

Manchmal dauert die Ausführung von Abfragen ca. 50 ms, andere über 250 s (und wenn Sie die 200-s-Abfrage oft genug ausführen, wird sie allem Anschein nach in einen Cache geladen und verkürzt sich auf ca. 50 ms).

Der Datensatz befindet sich in einer Tabelle mit einem einfachen Index (die Abfragen werden nicht über den Primärindex ausgeführt, sodass der gesamte 3,5-GB-Datensatz gescannt wird).


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';

Die ausgeführte Abfrage ist diese. SELECT * FROM cdrs_processed WHERE CorrelationID='<some guid>' ORDER BY Id; Unterschiedliche GUIDs haben unterschiedliche Abfrageantwortzeiten. Die interessanten Teile hier sind diese:

  1. Wenn ein PCAP über den Datenverkehr ausgeführt wird, antwortet der Server bei einer leistungsfähigen Abfrage (d. h. die Datensätze werden in ~50 ms zurückgegeben) zuerst mit den Spaltenüberschriften und dann mit den Daten. Wenn ein CorrelationID-Wert ausgewählt wird, der zu einem langsamen Lesen führt, zeigt der PCAP-Datenverkehr die Verbindung und Abfrage an, dann eine ganze Reihe von TCP-KeepAlive-Nachrichten, und erst dann (wenn es nicht zu einer Zeitüberschreitung gekommen ist) werden die Spaltenüberschriften und die Daten gesendet.

  2. Die bereitgestellte Clickhouse-Server-Software läuft auf einem AWS EC2 r5a.xlarge-Knoten, der nur minimale Abfragen empfängt (1-2/Sekunde), und lässt die 4 vCPUs der EC2-Instanz aus irgendeinem bizarren Grund zu 100 % laufen. Dieser Server hat dieselben Abfrageleistungsprobleme wie wenn wir die Daten aus einem Backup nehmen und sie in einem lokalen Docker-Image wiederherstellen, auf dem der Clickhouse-Server auf einem Entwicklersystem läuft.

  3. Beim Debuggen der Abfrage verwenden wir clickhouse-clientund führen sie aus set send_logs_level='trace';, bevor wir die Abfrage ausführen. Wenn es sich um eine leistungsstarke Abfrage handelt, erhalten wir die Fun-Protokolle von.

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

und alles ist gut, aber wenn es eine langsame Abfrage ist, wird es interessant. Die erste Zeile dieser Protokollzeile wird entsprechend mit dem Zeitstempel gedruckt, die zweite und die folgenden Zeilen werden erst gedruckt, wenn die Abfrage abgeschlossen ist, enthalten aber den Zeitstempel, als wären sie zum richtigen Zeitpunkt veröffentlicht worden. d. h.

Diese Zeile wird ausgedruckt.

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

Dann passiert nichts, bis 2023.09.06 05:31:35.309735alle restlichen Trace-Linien ausgedruckt sind, wie die unten. (Ich habe davon ein Video gemacht.)

[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. Als nächstes war der Server0 in den letzten 6+ Stunden ruhig, es gab keinerlei Anfragen an ihn, das einzige, was an ihn gesendet wurde, waren Prometheus-Metriken-Scrapings. Dennoch scrollen die Trace-Logs ständig vorbei mit
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

was für mich darauf hinweist, dass es versucht, eine Art von Abfragen/Zusammenführungen/Einfügungen zu verarbeiten.

Die eine Client-Anwendung (die seit 6 Stunden abgeschaltet ist) verarbeitet höchstens 1-2 Anfragen/Sekunde. In dieser Mischung könnte eine Aktualisierungsanfrage enthalten sein, aber ich kann diese stattdessen durch eine Einfügung ersetzen und mich auf das ReplacingMergeTreeVerhalten verlassen.

Kann jemand Ideen liefern, wo/was man nach etwas suchen soll, das geändert oder optimiert werden muss? Das Fehlen eines Index in den Daten scheint für einige der Abfragen kein Problem zu sein, da der sequentielle Scan in diesem Stadium leistungsfähig genug ist. Wir versuchen, eine zuverlässige Abfrageleistung zu erzielen, damit wir die richtigen Indizes/materialisierten Ansichten/Projektionen identifizieren können, die wir in den Daten benötigen, um zu sehen, wie sie sich auswirken, aber da wir von Clickhouse keine zuverlässige Leistung erhalten können...).

verwandte Informationen