Posted inDatabase

pt-query-digestでMySQL Slow Query Logを解析：データベース低速化の真犯人を特定する

Database tutorial - IT technology blog
Database tutorial - IT technology blog

データベースが遅い、でも原因が見えない

バックエンドエンジニアなら誰でも一度は経験するシナリオがある。アプリが突然重くなり、ユーザーから苦情が来る。でもサーバーを見るとCPUは30%、RAMにも余裕がある。問題はどこにあるのか？

答えはたいていデータベースにある。一部のクエリが不釣り合いな時間を消費しているのだ。MySQL、PostgreSQL、MongoDBとさまざまなプロジェクトで使ってきたが、パフォーマンスのデバッグという点では、MySQLには見落とされがちな強力な武器がある。Percona Toolkitに含まれるpt-query-digestだ。

この記事では本題に直入りする。Slow Query Logを有効化してデータを収集し、pt-query-digestで最適化すべきクエリを正確に特定する。もう当てずっぽうはいらない。

始める前に理解しておくべき2つのこと

Slow Query Logとは何か？

MySQLには、一定のしきい値より長く実行されたクエリをすべてログファイルに記録する機能がある。これがSlow Query Logだ。デフォルトではI/Oオーバーヘッドのため無効になっているが、パフォーマンスをデバッグする際には最も重要な情報源となる。

問題はこのログファイルが非常に長く、読みにくいことだ。手作業で読んでも、ほとんど何も得られない。本番システムが数時間動けば、数万行のログが生成される。

pt-query-digestは何をするのか？

pt-query-digestはPercona Toolkit — PerconaがMySQL/MariaDBの管理・最適化のために開発したコマンドラインユーティリティ集 — に含まれるツールだ。Slow Query Logを読み込み、類似クエリをグループ化し（パラメータの値が異なっていても）、統計をまとめる。どのクエリが最も多く実行されているか、どのクエリが合計時間を最も消費しているか、どのクエリの平均実行時間が最も長いかがわかる。

結果：5万行のログが、優先順位付きランキング付きの2ページのレポートに圧縮される。

MySQLでSlow Query Logを有効化する

開始するためにMySQLを再起動する必要はない。実行中のセッションで直接有効化できる：

-- rootユーザーでMySQLに接続
mysql -u root -p

-- Slow Query Logを有効化
SET GLOBAL slow_query_log = 'ON';

-- 時間のしきい値（秒）— これ以上かかったクエリがログに記録される
SET GLOBAL long_query_time = 1;

-- インデックスを使用しないクエリも記録する
SET GLOBAL log_queries_not_using_indexes = 'ON';

-- ログファイルの場所を確認
SHOW VARIABLES LIKE 'slow_query_log_file';

永続的に有効化（再起動後も保持）したい場合は、/etc/mysql/mysql.conf.d/mysqld.cnf（Ubuntu）または/etc/my.cnfに追加する：

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 1
log_queries_not_using_indexes = 1

その後、再起動する：sudo systemctl restart mysql

すぐにテストデータを取得するには、いくつかの遅いクエリを実行してみる：

-- インデックスを使用しないクエリ — ログに記録される
SELECT * FROM orders WHERE YEAR(created_at) = 2024;

-- またはSLEEPで実際の負荷を作成
SELECT SLEEP(2);

Percona Toolkitのインストール

Ubuntu/Debianの場合：

# Perconaリポジトリを追加
wget https://repo.percona.com/apt/percona-release_latest.$(lsb_release -sc)_all.deb
sudo dpkg -i percona-release_latest.$(lsb_release -sc)_all.deb
sudo apt-get update

# Percona Toolkitをインストール
sudo apt-get install percona-toolkit

# バージョン確認
pt-query-digest --version

CentOS/RHELの場合：

sudo yum install https://repo.percona.com/yum/percona-release-latest.noarch.rpm
sudo yum install percona-toolkit

pt-query-digestでログを解析する

システムをしばらく稼働させた後（本番では十分なデータを得るため最低数時間）、解析コマンドを実行する：

# 基本的な解析
pt-query-digest /var/log/mysql/mysql-slow.log

# ワースト5クエリのみ表示
pt-query-digest --limit 5 /var/log/mysql/mysql-slow.log

# 直近1時間のログのみ解析
pt-query-digest --since '1h' /var/log/mysql/mysql-slow.log

# レポートをファイルに保存して後で確認
pt-query-digest /var/log/mysql/mysql-slow.log > /tmp/slow-query-report.txt

レポートの読み方

pt-query-digestの出力には主に2つのセクションがある。最初は全体的なサマリー：

# 120 queries in 0.5k lines, 0.00 QPS, 0x concurrency ______________
# Time range: 2024-01-15 09:00:00 to 2024-01-15 11:00:00
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           245s   100ms      8s      2s      5s      1s      2s
# Lock time          120ms     0us    30ms     1ms     5ms     3ms   500us
# Rows sent          1.50k       1     500      13     100      50       5
# Rows examined     45.00k       1   5000     375    2000     800     100

2番目のセクションはクエリグループの一覧で、合計実行時間（Response time）順にランキングされている。これが重要なポイントで、上から読んでいく：

# Query 1: 0.50 QPS, 4.00x concurrency, ID 0xABC123 at byte 1234
# Scores: V/M = 0.10
# Time range: all events
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          5      60
# Exec time     40%    98s     1s      8s      1s      5s      1s      1s
# Rows examined 60%  27000     50    5000     450    2000     800     100

# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM orders
WHERE YEAR(created_at) = 2024
AND status = 'pending'\G

最も注目すべき3つの数値：

  • Count：解析期間中にこのクエリが何回実行されたか
  • Exec time（合計）：総実行時間 — 全スロークエリ時間の40%がこのクエリに集中している
  • Rows examined：MySQLが結果を返すためにスキャンした行数 — この値が高いとインデックス不足のサイン

レポートから最適化アクションへ

最も問題のあるクエリを特定したら、次のステップはEXPLAINを実行してMySQLの実行方法を確認することだ：

EXPLAIN SELECT * FROM orders
WHERE YEAR(created_at) = 2024
AND status = 'pending';

typeカラムにALLと表示されるのは赤信号だ。MySQLがインデックスを使わずにテーブル全体をスキャンしている。これがレポートで実行時間が8秒に達していた原因だ。

上記クエリの問題は、YEAR()関数がカラムをラップしているためMySQLがインデックスを使えないことだ。書き直してみよう：

-- 関数を使う方法（インデックスが使えない）
SELECT * FROM orders WHERE YEAR(created_at) = 2024;

-- created_atのインデックスを使えるように書き直し
SELECT * FROM orders
WHERE created_at >= '2024-01-01'
AND created_at < '2025-01-01'
AND status = 'pending';

-- 2つのカラムに対する複合インデックスを作成
CREATE INDEX idx_orders_created_status
ON orders (created_at, status);

インデックスを作成後、EXPLAINを再実行する。typeカラムがALLからrangeまたはrefに変わり、rowsが大幅に減少していなければならない。

修正をデプロイした後にもう一つやっておくことがある。数時間ログを記録させてからpt-query-digestを再実行する。修正前後のレポートを比較して、そのクエリがまだトップに現れるか、実行時間が減少しているかを確認する。最適化が本当に効果的かどうかを確かめる唯一の方法だ。

まとめ

pt-query-digestは複雑なツールではないが、使い所が明確だ。数万行の煩雑なログから、具体的な数値を伴ったランキングが得られる。実際には、上位2〜3クエリを修正するだけで明確な違いを感じられることが多い。適切な場所にインデックスを一つ追加するだけで、レスポンスタイムが数秒から100ms以下に下がることもある。

手順：Slow Query Logを有効化 → 数時間稼働 → pt-query-digest実行 → 上位クエリをEXPLAIN → インデックスを追加または書き直し → 修正前後のレポートを比較。トップに問題のあるクエリが残らなくなるまで繰り返す。

Share:
Tags: