Diagnostiquer les requêtes lentes

Commencez par regrouper les requêtes initiales terminées par normalized_query_hash. Cela permet de distinguer les modèles de requêtes récurrents des exécutions lentes isolées. La requête suivante classe les modèles par durée médiane et fournit un exemple de requête pour chaque modèle :

SELECT
    normalized_query_hash,
    count() AS executions,
    quantile(0.5)(query_duration_ms) AS median_duration_ms,
    max(query_duration_ms) AS max_duration_ms,
    formatReadableSize(avg(read_bytes)) AS avg_read_bytes,
    formatReadableSize(max(memory_usage)) AS max_memory,
    any(query) AS example_query
FROM clusterAllReplicas('default', merge('system', '^query_log'))
WHERE type = 'QueryFinish'
  AND is_initial_query = 1
  AND query_kind = 'Select'
  AND event_time >= now() - INTERVAL 1 HOUR
  AND has(databases, 'nyc_taxi')
GROUP BY normalized_query_hash
HAVING executions >= 2
ORDER BY median_duration_ms DESC
LIMIT 10
SETTINGS skip_unavailable_shards = 1

SELECT
    normalized_query_hash,
    count() AS executions,
    quantile(0.5)(query_duration_ms) AS median_duration_ms,
    max(query_duration_ms) AS max_duration_ms,
    formatReadableSize(avg(read_bytes)) AS avg_read_bytes,
    formatReadableSize(max(memory_usage)) AS max_memory,
    any(query) AS example_query
FROM merge('system', '^query_log')
WHERE type = 'QueryFinish'
  AND is_initial_query = 1
  AND query_kind = 'Select'
  AND event_time >= now() - INTERVAL 1 HOUR
  AND has(databases, 'nyc_taxi')
GROUP BY normalized_query_hash
HAVING executions >= 2
ORDER BY median_duration_ms DESC
LIMIT 10

Utilisez executions pour distinguer un workload récurrent de queries isolées. Un pattern présentant une durée médiane élevée, des exécutions fréquentes ou une consommation de ressources importante constitue un candidat plus pertinent pour une investigation qu'une unique exécution lente.

Pour dresser un rapide inventaire, la requête suivante liste l'exécution terminée la plus lente pour un maximum de cinq query patterns distincts sur le jeu de données des taxis de NYC. Elle exclut les statements de chargement du jeu de données ainsi que les exécutions répétées d'un même pattern. À l'étape suivante, vous restreindrez le query history aux exécutions correspondant au normalized_query_hash sélectionné ci-dessus.

-- Rechercher les 5 requêtes les plus longues de la base de données nyc_taxi au cours de la dernière heure
SELECT
    normalized_query_hash,
    type,
    event_time,
    query_duration_ms,
    query,
    read_rows,
    tables
FROM clusterAllReplicas('default', merge('system', '^query_log'))
WHERE has(databases, 'nyc_taxi')
  AND event_time >= now() - INTERVAL 1 HOUR
  AND type = 'QueryFinish'
  AND is_initial_query = 1
  AND query_kind = 'Select'
ORDER BY query_duration_ms DESC
LIMIT 1 BY normalized_query_hash
LIMIT 5
SETTINGS skip_unavailable_shards = 1
FORMAT VERTICAL

-- Rechercher les 5 requêtes les plus longues de la base de données nyc_taxi au cours de la dernière heure
SELECT
    normalized_query_hash,
    type,
    event_time,
    query_duration_ms,
    query,
    read_rows,
    tables
FROM merge('system', '^query_log')
WHERE has(databases, 'nyc_taxi')
  AND event_time >= now() - INTERVAL 1 HOUR
  AND type = 'QueryFinish'
  AND is_initial_query = 1
  AND query_kind = 'Select'
ORDER BY query_duration_ms DESC
LIMIT 1 BY normalized_query_hash
LIMIT 5
FORMAT VERTICAL

Query id: e3d48c9f-32bb-49a4-8303-080f59ed1835

Row 1:
──────
normalized_query_hash: 11000678248135956062
type:              QueryFinish
event_time:        2024-11-27 11:12:36
query_duration_ms: 2967
query:             WITH
  dateDiff('s', pickup_datetime, dropoff_datetime) as trip_time,
  trip_distance / trip_time * 3600 AS speed_mph
SELECT
  quantiles(0.5, 0.75, 0.9, 0.99)(trip_distance)
FROM
  nyc_taxi.trips_small_inferred
WHERE
  speed_mph > 30
FORMAT JSON
read_rows:         329044175
tables:            ['nyc_taxi.trips_small_inferred']

Row 2:
──────
normalized_query_hash: 4194765292165295011
type:              QueryFinish
event_time:        2024-11-27 11:11:33
query_duration_ms: 2026
query:             SELECT
    payment_type,
    COUNT() AS trip_count,
    formatReadableQuantity(SUM(trip_distance)) AS total_distance,
    AVG(total_amount) AS total_amount_avg,
    AVG(tip_amount) AS tip_amount_avg
FROM
    nyc_taxi.trips_small_inferred
WHERE
    pickup_datetime >= '2009-01-01' AND pickup_datetime < '2009-04-01'
GROUP BY
    payment_type
ORDER BY
    trip_count DESC;

read_rows:         329044175
tables:            ['nyc_taxi.trips_small_inferred']

Row 3:
──────
normalized_query_hash: 1891814463795712754
type:              QueryFinish
event_time:        2024-11-27 11:12:17
query_duration_ms: 1860
query:             SELECT
  avg(dateDiff('s', pickup_datetime, dropoff_datetime))
FROM nyc_taxi.trips_small_inferred
WHERE passenger_count = 1 or passenger_count = 2
FORMAT JSON
read_rows:         329044175
tables:            ['nyc_taxi.trips_small_inferred']

Le champ query_duration_ms contient la durée de la requête en millisecondes. Dans ces résultats, la requête la plus longue a duré 2 967 ms.

Vous pouvez également identifier les requêtes candidates en fonction de l'utilisation des ressources plutôt que de la durée des requêtes :

-- Requêtes consommant le plus de mémoire
SELECT
    type,
    event_time,
    query_id,
    formatReadableSize(memory_usage) AS memory,
    ProfileEvents.Values[indexOf(ProfileEvents.Names, 'UserTimeMicroseconds')] AS userCPU,
    ProfileEvents.Values[indexOf(ProfileEvents.Names, 'SystemTimeMicroseconds')] AS systemCPU,
    (ProfileEvents['CachedReadBufferReadFromCacheMicroseconds']) / 1000000 AS FromCacheSeconds,
    (ProfileEvents['CachedReadBufferReadFromSourceMicroseconds']) / 1000000 AS FromSourceSeconds,
    normalized_query_hash
FROM clusterAllReplicas('default', merge('system', '^query_log'))
WHERE has(databases, 'nyc_taxi')
  AND type = 'QueryFinish'
  AND is_initial_query = 1
  AND query_kind = 'Select'
  AND event_time >= now() - INTERVAL 2 DAY
  AND user NOT ILIKE '%internal%'
ORDER BY memory_usage DESC
LIMIT 30
SETTINGS skip_unavailable_shards = 1

-- Requêtes consommant le plus de mémoire
SELECT
    type,
    event_time,
    query_id,
    formatReadableSize(memory_usage) AS memory,
    ProfileEvents.Values[indexOf(ProfileEvents.Names, 'UserTimeMicroseconds')] AS userCPU,
    ProfileEvents.Values[indexOf(ProfileEvents.Names, 'SystemTimeMicroseconds')] AS systemCPU,
    (ProfileEvents['CachedReadBufferReadFromCacheMicroseconds']) / 1000000 AS FromCacheSeconds,
    (ProfileEvents['CachedReadBufferReadFromSourceMicroseconds']) / 1000000 AS FromSourceSeconds,
    normalized_query_hash
FROM merge('system', '^query_log')
WHERE has(databases, 'nyc_taxi')
  AND type = 'QueryFinish'
  AND is_initial_query = 1
  AND query_kind = 'Select'
  AND event_time >= now() - INTERVAL 2 DAY
  AND user NOT ILIKE '%internal%'
ORDER BY memory_usage DESC
LIMIT 30

Une seule exécution lente peut être une valeur aberrante due à une requête ponctuelle ou à une charge système temporaire. Avant d’inspecter le plan de requête, examinez plusieurs exécutions terminées présentant le même normalized_query_hash, identique pour les requêtes qui ne diffèrent que par leurs valeurs littérales. Choisissez une exécution représentative de la durée et de l’utilisation habituelles des ressources pour ce modèle.

Remplacez la valeur affectée à selected_hash par le normalized_query_hash du modèle que vous souhaitez examiner :

WITH toUInt64(123456789) AS selected_hash
SELECT
    event_time,
    query_id,
    query_duration_ms,
    read_rows,
    read_bytes,
    memory_usage,
    query
FROM clusterAllReplicas('default', merge('system', '^query_log'))
WHERE type = 'QueryFinish'
  AND is_initial_query = 1
  AND normalized_query_hash = selected_hash
  AND event_time >= now() - INTERVAL 1 HOUR
ORDER BY event_time DESC
LIMIT 10
SETTINGS skip_unavailable_shards = 1;

WITH toUInt64(123456789) AS selected_hash
SELECT
    event_time,
    query_id,
    query_duration_ms,
    read_rows,
    read_bytes,
    memory_usage,
    query
FROM merge('system', '^query_log')
WHERE type = 'QueryFinish'
  AND is_initial_query = 1
  AND normalized_query_hash = selected_hash
  AND event_time >= now() - INTERVAL 1 HOUR
ORDER BY event_time DESC
LIMIT 10;

1. Recherchez les exécutions présentant des valeurs read_rows et read_bytes similaires.
2. Comparez query_duration_ms et memory_usage pour ces exécutions.
3. Sélectionnez le query_id dont le query_duration_ms est le plus proche de la médiane.

Les exemples de résultats du journal de requêtes montrent que chaque candidat a lu environ 329,04 millions de lignes. Pour référence, confirmez le nombre de lignes de la table d’exemple :

SELECT count()
FROM nyc_taxi.trips_small_inferred

Query id: 733372c5-deaf-4719-94e3-261540933b23

   ┌───count()─┐
1. │ 329044175 │ -- 329.04 million
   └───────────┘

La table contient 329,04 millions de lignes, soit approximativement le même nombre que celui indiqué dans read_rows pour chaque candidat. Cela suggère que les requêtes ont parcouru la majeure partie, voire la totalité, de la table, mais n’indique pas pourquoi ces lignes ont été lues ni si ce volume est approprié pour la requête. Examinez ensuite le plan de requête pour voir comment ClickHouse a sélectionné et traité les données.

Après avoir choisi une exécution représentative, utilisez EXPLAIN pour examiner comment ClickHouse planifie la requête sans l’exécuter. La sortie indique les opérations que ClickHouse prévoit d’effectuer et la façon dont les données circulent entre elles, apportant davantage de contexte aux mesures du journal des requêtes.

Pour une présentation détaillée des formats de sortie disponibles, consultez Comprendre l’exécution des requêtes avec l’analyseur. Dans cet exemple, EXPLAIN montre comment ClickHouse prévoit de lire et de filtrer les données, ainsi que s’il peut en ignorer une partie.

La sortie se présente sous la forme d’un arbre d’opérations qui montre comment ClickHouse prévoit de lire, filtrer et traiter les données. Les opérations enfants apparaissent sous leurs opérations parentes. Commencez par l’opération de lecture la plus profonde, puis remontez le plan pour voir comment ClickHouse transforme les données en résultat final.

Pour cet exemple, examinez la requête de calcul de vitesse dans les résultats du journal des requêtes :

EXPLAIN actions = 1, compact = 1, pretty = 1, indexes = 1
WITH
    dateDiff('s', pickup_datetime, dropoff_datetime) AS trip_time,
    (trip_distance / trip_time) * 3600 AS speed_mph
SELECT quantiles(0.5, 0.75, 0.9, 0.99)(trip_distance)
FROM nyc_taxi.trips_small_inferred
WHERE speed_mph > 30

La sortie comprend les opérations suivantes. Certains détails, comme le nombre de parts et de granules, dépendent du mode de stockage des données :

Output: quantiles(0.5, 0.75, 0.9, 0.99)(trip_distance)

Aggregating
│  Aggregates: quantiles(0.5, 0.75, 0.9, 0.99)(trip_distance)
└──Filter
   │  Filter column: trip_distance / dateDiff('s', pickup_datetime, dropoff_datetime) * 3600 > 30
   └──ReadFromMergeTree (nyc_taxi.trips_small_inferred)

De bas en haut, le plan se rapporte à la requête comme suit :

1. ReadFromMergeTree lit la table nyc_taxi.trips_small_inferred. L'absence de section Indexes, associée au fait que read_rows correspond au nombre de lignes de la table, montre que ClickHouse lit l'intégralité de la table.
2. Filter affiche l'expression développée pour speed_mph > 30. Pour chaque ligne lue, ClickHouse calcule la durée et la vitesse du trajet, puis ne conserve que les lignes dont la vitesse dépasse 30 miles par heure.
3. Aggregating calcule les quantiles à partir des valeurs filtrées de trip_distance.

Ce plan met en évidence trois sources de travail à tester : la lecture de toutes les lignes, le calcul de speed_mph lors du filtrage et le calcul des quantiles.