MySQLのスロークエリログを有効化し、pt-query-digestでDBのボトルネックを特定する - ITFROMZERO - Share tobe shared! サーバーを再起動せずにMySQLのスロークエリログを有効化し、pt-query-digestを使って本番環境でCPU負荷を引き起こしているクエリを分析・ランク付けする実践ガイド。

Table of Contents

データベースが突如高負荷に：何から手をつけるべきか？

Webサイトが順調に稼働していた矢先、サーバーのCPU使用率が突然99%に跳ね上がる。APIのレスポンスタイムは50msから8秒へと急激に悪化し、データベースの接続数はmax_connectionsの上限に達し、ユーザー画面には504 Gateway Timeoutエラーが頻発する——。こうした問題の原因は、必ずしもシステム全体にあるとは限りません。多くの場合、インデックスが考慮されていないわずか数本のクエリが裏で何百万件ものレコードをフルスキャンし、リソースを食い尽くしていることが原因です。

しかし、error.logを確認しても異常は見当たりません。リアルタイム監視ツールであるmytopで稼働中のスレッドを確認することはできても、クエリの構文自体は正しくエラーを吐いているわけでもなく、ただ「処理に異常に時間がかかっている」だけだからです。1日に何百万リクエストも処理する環境において、どのクエリがサーバーをダウンさせようとしているのかを当てずっぽうで探すのは不可能です。

中核となる2つのツール：Slow Query Logとpt-query-digest

推測ではなく実際のデータに基づいて問題を根本解決するには、Slow Query Log（スロークエリログ）とpt-query-digestという2つの強力なツールが必要です。

Slow Query Logとは？

MySQLには標準でSlow Query Log機能が備わっています。システム変数long_query_timeで閾値（例: 0.5秒）を設定するだけで、この閾値を超えて実行されたクエリや、インデックスを使用せずにテーブルスキャンを行ったクエリが、専用のログファイルに漏れなく記録されます。

なぜ生のログファイルだけでは不十分なのか？

中規模のECサイトが24時間稼働すると、ログファイルは2GBに達し、行数が30万行を超えることも珍しくありません。このような巨大ファイルをlessやgrepで手動解析するのは現実的ではありません。

そこで登場するのが、Percona Toolkitに含まれるpt-query-digestです。このツールはログファイル全体を解析し、同じ構造を持つクエリ（具体的なパラメータをプレースホルダー?に置き換えたもの）ごとにグループ化し、実行時間の占有率を計算して、システムに最も負荷をかけているクエリをランキング形式で提示してくれます。

実際の設定手順と分析フロー

ステップ1：MySQLを再起動せずにSlow Query Logを有効化する

本番環境のピーク時間帯にMySQLを再起動するのは絶対に避けたいところです。幸いなことに、MySQLのセッション内から動的にログ設定を反映させることができます。

mysql -u root -p

続いて、以下のコマンドを実行してランタイム設定を適用します。

-- スロークエリログを有効化
SET GLOBAL slow_query_log = 'ON';

-- ログの出力先パス
SET GLOBAL slow_query_log_file = '/var/log/mysql/mysql-slow.log';

-- 0.5秒以上かかったクエリを記録（MySQL 5.1以降はマイクロ秒単位に対応）
SET GLOBAL long_query_time = 0.5;

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

注意点として、long_query_timeは0.2や0.5といった小数点以下の値にも対応しています。デフォルトの1.0秒という閾値は、高トラフィックなWebシステムにとっては長すぎる場合が多いためです。

サーバー再起動後もこの設定を永続化させるために、MySQLの設定ファイル（通常は/etc/mysql/mysql.conf.d/mysqld.cnfまたは/etc/my.cnf）を開き、[mysqld]セクションに以下を追加します。

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

ログの書き込みがサイレントに失敗するのを防ぐため、mysqlユーザーにファイルの書き込み権限が付与されているか確認・設定します。

sudo touch /var/log/mysql/mysql-slow.log
sudo chown mysql:mysql /var/log/mysql/mysql-slow.log
sudo chmod 640 /var/log/mysql/mysql-slow.log

ステップ2：Percona Toolkitのインストール

Ubuntu/Debian環境ではapt経由でインストールします。

sudo apt update
sudo apt install -y percona-toolkit

CentOS、RHEL、またはAlmaLinux環境の場合：

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

ステップ3：pt-query-digestによるログファイルの分析

十分な信頼性を持つサンプルデータを収集するため、システムを少なくとも1回のピーク時間帯（2〜4時間程度）稼働させておきます（検証環境であればmysqlslapによる負荷テストで擬似的にスロークエリを発生させるのも有効です）。その後、レポートをテキストファイルに出力します。

pt-query-digest /var/log/mysql/mysql-slow.log > /tmp/slow_report.txt
less /tmp/slow_report.txt

レポートは主に以下の3つのセクションで構成されています。

Overall Metrics: 総実行時間、ユニーククエリ数、システムの平均負荷。
Profile: 実行時間占有率（Response Time %）順に並べられたクエリグループのランキング。
Query Details: 各クエリの詳細統計：実行回数、最小/最大/95%パーセンタイル実行時間、走査行数と返却行数の比率など。

ランキング一覧は以下のような形式で出力されます。

# Profile
# Rank Query ID           Response time  Calls R/Call   V/M   Item
# === ================== ============== ====== ======== ===== ==============
#   1 0x4F18B9A6D2C8E7B1 1420.50s 65.2%   2300   0.6176  0.02 SELECT orders
#   2 0x9A3B5C7D1E8F2A40  420.10s 19.3%    120   3.5008  0.15 SELECT users

ここで、単体で3.5秒かかっているRank 2のクエリに惑わされてはいけません。Rank 1のクエリ（SELECT orders）は1回の実行こそ0.61秒ですが、2,300回も呼び出されており、データベース全体の稼働時間の65.2%を占有しています。このクエリを最適化するだけで、サーバー負荷の3分の2近くを解消できる計算になります。

ステップ4：Rows examine（走査行数）とRows sent（返却行数）を読み解いて最適化する

Rank 1クエリの詳細情報までスクロールし、以下のパラメータを確認します。

# Attribute          pct   total     min     max     avg     95%  stddev  median
# Exec time           65   1420s   100ms      2s   617ms      1s   200ms   500ms
# Rows examine        88   1200M     50k    600k    521k    580k     50k    500k
# Rows sent            1    2.3k       1       5       1       2       1       1

データから以下の事実が読み取れます。

Rows examine: 平均521,000行をスキャンしている。
Rows sent: 実際に返している結果はわずか1行のみ。

521,000 : 1 という極端な比率は、フルテーブルスキャン（Full Table Scan）が発生している明確な証拠です。MySQLはたった1行のデータを取得するために、50万件以上のレコードを総当たりで探索しています。

EXPLAINを使って実行計画を確認してみましょう。オプティマイザの判断理由をさらに詳細に追跡したい場合は、OPTIMIZER_TRACEによるインデックス選択ロジックの解析も役立ちます。

EXPLAIN SELECT * FROM orders WHERE status = 'PENDING' AND customer_id = 9821;

もしtype列にALLと表示されていれば、直ちに複合インデックス（Composite Index）を追加します。要件に応じてテーブルへのアクセス自体を省くカバリングインデックスの活用も検討すると、さらなる性能向上が見込めます。

ALTER TABLE orders ADD INDEX idx_customer_status (customer_id, status);

インデックス作成後、走査行数は521,000行からわずか1行に激減し、レスポンスタイムも600ms以上から2ms未満へと劇的に改善されます。なお、インデックスを無計画に増やし続けると書き込み処理の遅延を招くため、未使用インデックスを特定して削除する定期的なメンテナンスも欠かせません。

本番環境での注意点：数千万件規模のレコードを持つ巨大テーブルに対して通常のALTER TABLEを実行すると、テーブルロックやレプリケーション遅延を引き起こす恐れがあります。ダウンタイムを回避するため、pt-online-schema-changeやgh-ostといったオンラインDDLツールの活用を検討してください。

まとめ

データベースの最適化は勘や推測で行うものではありません。Slow Query Logを有効化してボトルネックの現場を正確に記録し、pt-query-digestを用いて各クエリの影響度を数値化して可視化する——。この2つのツールを組み合わせることで、CPU時間がどこで浪費されているかをミリ秒単位で把握し、最もインパクトの大きいボトルネックを的確に解消できるようになります。