느린 쿼리 진단하기

느린 쿼리 진단하기

느린 쿼리 진단은 쿼리 기록에서 얻은 증거에서 시작해요. 이 가이드에서는 system.query_log를 사용해 반복되는 느린 쿼리 패턴을 찾고, 대표 실행을 고르고, 리소스 사용량을 검토하는 방법을 보여드릴게요. 그런 다음 EXPLAIN으로 쿼리 계획을 살펴보고, 쿼리나 스키마를 바꾸기 전에 병목에 대한 가설을 세울 거예요.

출처: 문서

본문

시작하기 전에 (Before you begin)

이 가이드의 예제는 nyc_taxi.trips_small_inferred 테이블을 사용해요. 그대로 실행하려면 아직 안 했다면 테이블을 만들고 데이터를 로드해주세요:

예제 데이터셋 설정하기

원본 Parquet 파일은 약 5.8 GB예요. 네트워크와 사용 가능한 리소스에 따라 로드에 몇 분이 걸릴 수 있어요.

CREATE DATABASE IF NOT EXISTS nyc_taxi;
USE nyc_taxi;

CREATE TABLE nyc_taxi.trips_small_inferred
ORDER BY () EMPTY
AS SELECT *
FROM s3(
    'https://datasets-documentation.s3.eu-west-3.amazonaws.com/nyc-taxi/clickhouse-academy/nyc_taxi_2009-2010.parquet',
    NOSIGN,
    Parquet
);

INSERT INTO nyc_taxi.trips_small_inferred
SELECT *
FROM s3(
    'https://datasets-documentation.s3.eu-west-3.amazonaws.com/nyc-taxi/clickhouse-academy/nyc_taxi_2009-2010.parquet',
    NOSIGN,
    Parquet
);

이 가이드의 쿼리 로그 결과를 재현하려면, 데이터셋 로드 후 예제 워크로드 쿼리 세 개를 모두 최소 두 번 실행해주세요. 그런 다음 완료된 실행이 아래 예제에서 사용 가능하도록 쿼리 로그를 flush해요:

SYSTEM FLUSH LOGS;

SYSTEM FLUSH LOGS를 실행할 수 없으면 쿼리 로그가 자동으로 flush될 때까지 기다린 뒤 첫 번째 조회를 다시 시도해요. 자신의 워크로드를 진단할 때는 system.query_log에 조사하려는 시간 범위의 완료된 실행이 포함되어 있는지 확인해주세요.

어떻게 동작하나요 (How it works)

기본적으로 ClickHouse는 완료된 쿼리에 대한 정보를 system.query_log 테이블에 기록해요. 각 레코드에는 쿼리 지속 시간, 읽은 행 수, CPU 및 메모리 사용량, 파일시스템 캐시 활동이 포함될 수 있어요. 이러한 측정값은 느린 쿼리 패턴을 식별하고 그들이 리소스를 어떻게 사용하는지 이해하는 데 도움이 돼요. 대표 실행을 고른 뒤 그 쿼리 계획을 검사해 쿼리가 시간을 어디에 쓰고 있을지 조사할 수 있어요. 클러스터에서 쿼리 로그 데이터는 각 노드에 로컬로 유지돼요. 이 가이드의 예제는 clusterAllReplicas로 모든 레플리카를 조회하고, merge를 사용해 현재 system.query_log 테이블과 시스템 테이블 스키마 변경 후 유지되는 버전별 query_log_N 테이블을 포함해요. 각 쿼리 로그 예제에는 클러스터형과 단일 노드 배포용 탭이 있어요. ClickHouse Cloud는 클러스터 예제에서 사용하는 default 클러스터를 제공해요. 자체 관리 배포에서는 default를 system.clusters에 나열된 클러스터로 바꾸세요.

예제는 skip_unavailable_shards를 설정해서, 일시적으로 사용할 수 없는 레플리카 때문에 진단 쿼리가 실패하지 않게 해요. 이는 특히 자동 확장 중에 유용해요. 건너뛴 레플리카의 레코드는 포함되지 않으므로 결과가 불완전할 수 있어요.

느린 쿼리 진단하기 (Diagnose a slow query)

쿼리 로그에 완료된 실행이 있으면 다음 세 단계를 순서대로 진행해요. 반복되는 느린 쿼리 패턴을 식별하고, 대표 실행을 고르고, 쿼리의 실행 계획을 검사할 거예요.

1. 후보 쿼리 식별하기

먼저 완료된 초기 쿼리를 normalized_query_hash로 그룹화해요. 이렇게 하면 반복되는 쿼리 패턴과 개별적인 느린 실행을 분리할 수 있어요. 다음 쿼리는 중앙값 지속 시간으로 패턴을 순위 매기고, 각 패턴에 대한 예제 쿼리를 포함해요:

• 클러스터

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

executions로 반복되는 워크로드와 고립된 쿼리를 구분해요. 중앙값 지속 시간이 높거나, 실행이 빈번하거나, 리소스 사용량이 높은 패턴은 단일 느린 실행보다 조사할 가치가 더 커요.

빠른 인벤토리로, 다음 쿼리는 NYC Taxi 데이터셋에서 최대 5개의 서로 다른 쿼리 패턴에 대한 가장 느린 완료 실행을 나열해요. 데이터셋 로딩 문과 같은 패턴의 반복 실행은 제외해요. 다음 단계에서 위에서 선택한 normalized_query_hash로 쿼리 기록을 좁힐 거예요.

• 클러스터

-- Find top 5 long running queries from nyc_taxi database in the last 1 hour
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

• 단일 노드

-- Find top 5 long running queries from nyc_taxi database in the last 1 hour
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']

query_duration_ms 필드는 쿼리 지속 시간을 밀리초로 담아요. 이 결과에서 가장 오래 걸린 쿼리는 2,967ms가 걸렸어요.

쿼리 지속 시간이 아닌 리소스 사용량을 기준으로 후보 쿼리를 식별할 수도 있어요:

리소스 집약적 쿼리 찾기

이 쿼리는 최근 쿼리를 메모리 사용량으로 순위 매기고 CPU 사용량을 포함해요. 결과는 워크로드와 배포에 따라 달라져요:

• 클러스터

-- Top queries by memory usage
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

• 단일 노드

-- Top queries by memory usage
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

2. 대표 쿼리 실행 고르기

단일 느린 실행은 임시 쿼리나 일시적 시스템 부하로 인한 이상치일 수 있어요. 쿼리 계획을 검사하기 전에 리터럴 값만 다른 쿼리에서 동일한 normalized_query_hash를 가진 완료 실행들을 여러 개 검토해요. 패턴의 전형적인 지속 시간과 리소스 사용량을 대표하는 실행을 골라요.

selected_hash에 할당된 값을 조사하려는 패턴의 normalized_query_hash로 바꿔주세요:

• 클러스터

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. read_rows와 read_bytes가 비슷한 실행을 찾아요.
2. 이 실행들의 query_duration_ms와 memory_usage를 비교해요.
3. query_duration_ms가 중앙값에 가장 가까운 query_id를 선택해요.

과거 쿼리 로그 결과는 캐시 상태와 시스템 부하에 따라 달라질 수 있으므로, 최적화 변경을 비교하는 데 쓰지 말고 조사할 쿼리를 고르는 데 사용해요. 쿼리 로그에 충분한 완료 실행이 없으면 비슷한 조건에서 쿼리를 몇 번 실행해요. 다음 가이드인 쿼리 병목 분리는 변경 비교를 위한 통제된 측정을 수집하는 방법을 설명해요.

예제 쿼리 로그 결과는 각 후보가 약 3억 2904만 행을 읽었음을 보여줘요. 맥락을 위해 예제 테이블의 행 수를 확인해요:

SELECT count()
FROM nyc_taxi.trips_small_inferred

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

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

테이블에는 3억 2904만 행이 있고, 각 후보의 read_rows에 보고된 것과 거의 동일해요. 이는 쿼리가 테이블의 대부분 또는 전부를 스캔했다는 뜻이지만, 왜 그 행들이 읽혔는지 또는 그 양이 쿼리에 적절한지는 식별하지 못해요. ClickHouse가 데이터를 어떻게 선택하고 처리했는지 보려면 다음으로 쿼리 계획을 검사해요.

3. 실행 계획 검사하기

대표 실행을 고른 뒤 EXPLAIN을 사용해 쿼리를 실행하지 않고 ClickHouse가 어떻게 계획하는지 검사해요. 출력은 ClickHouse가 수행할 것으로 예상하는 연산과 데이터가 그들 사이를 어떻게 이동하는지 보여줘서, 쿼리 로그의 측정값에 더 많은 맥락을 제공해요.

사용 가능한 출력 형식에 대한 자세한 소개는 Understanding query execution with the analyzer를 참고하세요. 이 예제에서 EXPLAIN은 ClickHouse가 데이터를 어떻게 읽고 필터링할지 계획하는지, 그리고 그중 일부를 건너뛸 수 있는지 보여줘요.

출력은 ClickHouse가 데이터를 읽고, 필터링하고, 처리할 것으로 예상하는 방식을 보여주는 연산 트리예요. 자식 연산은 부모 아래에 나타나요. 가장 깊은 읽기 연산에서 시작해, ClickHouse가 데이터를 최종 결과로 어떻게 변환하는지 보려면 계획을 따라 위로 올라가요.

이 예제에서는 쿼리 로그 결과에서 계산된 속도 쿼리를 검사해요:

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

출력에는 다음 연산이 포함돼요. part와 granule의 수 같은 세부사항은 데이터 저장 방식에 따라 달라져요:

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)

계획을 아래에서 위로 읽으면 쿼리에 다음과 같이 매핑돼요:

1. ReadFromMergeTree는 nyc_taxi.trips_small_inferred에서 읽어요. Indexes 섹션이 없고 read_rows가 테이블의 행 수와 일치하는 것으로 보아 ClickHouse가 전체 테이블을 읽는다는 걸 알 수 있어요.
2. Filter는 speed_mph > 30의 확장된 표현식을 보여줘요. 읽은 모든 행에 대해 ClickHouse는 여행 지속 시간과 속도를 계산하고, 시속 30마일을 넘는 행만 유지해요.
3. Aggregating은 필터링된 trip_distance 값에서 분위수를 계산해요.

이 계획은 테스트할 세 가지 작업 원인을 식별해요: 모든 행 읽기, 필터링 중 speed_mph 계산, 분위수 계산.

다음 단계 (Next steps)

다음으로 쿼리 병목 분리를 사용해 의심되는 작업 원인을 통제된 조건에서 테스트하는 방법을 배워요. 점진적으로 더 단순한 쿼리 형태를 비교해서 어떤 연산이 추가 조사를 받을 만한지 식별해요.

더 알아보기 (Learn more)

• Isolate query bottlenecks
• Understanding query execution with the analyzer
• EXPLAIN