느린 쿼리 진단 (system.query_log, ProfileEvents, 트레이스, EXPLAIN)

SELECT event_time, query_duration_ms AS ms, read_rows, result_rows,
       round(read_rows / greatest(result_rows, 1)) AS read_per_result,
       formatReadableSize(read_bytes) AS read, formatReadableSize(memory_usage) AS mem,
       user, substring(query, 1, 100) AS q
FROM system.query_log
WHERE type = 'QueryFinish' AND event_date = today()
  AND query_kind = 'Select'
ORDER BY query_duration_ms DESC
LIMIT 20;

SELECT normalized_query_hash AS h, count() AS n,
       quantile(0.5)(query_duration_ms) AS p50, quantile(0.95)(query_duration_ms) AS p95,
       max(query_duration_ms) AS max_ms,
       sum(read_rows) AS rows, any(substring(query, 1, 100)) AS sample
FROM system.query_log
WHERE type = 'QueryFinish' AND event_date >= today() - 7 AND query_kind = 'Select'
GROUP BY h
HAVING n > 10
ORDER BY p95 DESC
LIMIT 20;

EXPLAIN indexes = 1
SELECT count() FROM logs.events
WHERE ts >= '2026-10-01' AND service = 'api';

ReadFromMergeTree (logs.events)
Indexes:
  PrimaryKey
    Keys: ts, service
    Condition: and((ts in [1759276800, +Inf)), (service in ['api', 'api']))
    Parts: 12/40
    Granules: 1830/98211

SET send_logs_level = 'trace';
SELECT count() FROM logs.events WHERE ts >= today() - 1 AND user_id = 42;

<Debug> logs.events (SelectExecutor): Key condition: (column 0 in [20250, +Inf))
<Debug> logs.events (SelectExecutor): Selected 3/40 parts by partition key,
        3 parts by primary key, 412/9100 marks by primary key, 412 marks to read from 3 ranges
<Trace> logs.events (SelectExecutor): Spreading mark ranges among streams (default reading)
<Debug> executeQuery: Read 3375104 rows, 26.42 MiB in 0.183 sec., 18.4 million rows/sec.

SELECT query_duration_ms,
       ProfileEvents['SelectedParts'] AS parts, ProfileEvents['SelectedMarks'] AS marks,
       ProfileEvents['SelectedRows'] AS sel_rows,
       ProfileEvents['OSCPUVirtualTimeMicroseconds'] / 1000 AS cpu_ms,
       ProfileEvents['DiskReadElapsedMicroseconds'] / 1000 AS disk_ms,
       ProfileEvents['NetworkReceiveElapsedMicroseconds'] / 1000 AS net_ms,
       ProfileEvents['S3ReadMicroseconds'] / 1000 AS s3_ms,
       ProfileEvents['ReadCompressedBytes'] AS compressed_bytes,
       ProfileEvents['QueryCacheHits'] AS cache_hit
FROM system.query_log
WHERE query_id = '...' AND type = 'QueryFinish';

SET query_profiler_cpu_time_period_ns = 10000000,   -- 10ms 마다 샘플
    query_profiler_real_time_period_ns = 10000000;
SELECT ... ;  -- 느린 쿼리

SELECT count() AS samples,
       arrayStringConcat(
           arrayReverse(arrayMap(x -> demangle(addressToSymbol(x)), trace)), ';') AS stack
FROM system.trace_log
WHERE query_id = '...' AND trace_type = 'CPU'
GROUP BY trace
ORDER BY samples DESC
LIMIT 10;