はじめに
MySQL のスロークエリログは、long_query_time で指定された閾値 (デフォルトでは10秒) を超える SQL ステートメントで構成され、これらのクエリが実行に時間を要する場合、最適化の候補となります。このようなスロークエリを特定し、分析するためには Percona 社が提供する Percona Toolkit の
一部である pt-query-digest や mysqldumpslow が利用されます。
pt-query-digest を使用するとスロークエリを分析し、合計実行時間順 (デフォルト) や発生回数などでランキング形式で結果を出力します。
pt-query-digest は、mysqldumpslow を使用した時よりも、より詳細なレポートを確認することができます。また、複数のフォーマットに対応しており、テキストレポート形式、JSON 形式などの形式で
レポートを出力できることも mysqldumpslow にはない利点です。
pt-query-digest には --since, --until オプションを使用し、特定の時間のログを出力することができます。しかし --since, --until オプションを使用しても指定した期間での発生回数しか確認できず、例えば1週間分のスロークエリ発生回数を1日単位で確認するといったことができません。
(厳密には確認することは可能ですが、1週間分の場合 pt-query-digest を7回実行する必要があります。)
月単位や日単位での発生回数を一目で確認する方法がないかと調べてみた結果、pt-query-digest と awk コマンドを使用することでグループ集計が行えることを知りましたので、その方法を紹介したいと思います。
Percona Toolkit のダウンロード
Percona Toolkit は、以下からダウンロードすることができます。
主なオプション
よく使用するオプションをピックアップして以下に記載します。
- since, until
集計したい期間を指定します。
例$ pt-query-digest --since="2024-01-01" --until="2024-01-08" slow-query.log
- limit
出力行数を制限します。
例$ pt-query-digest --limit 10 slow-query.log
- group-by
指定された値に基づいて結果をグループ化します。
設定できる値の代表的なものを以下に記載いたしますが、詳細はこちらのリファレンスをご確認下さい。
・fingerprint (デフォルト)
同じ構造のクエリがグループ化されます。
以下のクエリは select name, password from user where id=? のグループとして扱われ
ます。
|
1 2 |
$ SELECT name, password FROM user WHERE id='12823'; $ SELECT name, password FROM user WHERE id=5; |
例 $ pt-query-digest --group-by fingerprint slow-query.log
・distill
出力結果の SQL は SELECT A FROM B は SELECT A のように取得項目でまとめられます。
例 $ pt-query-digest --group-by distill slow-query.log
・tables
クエリがテーブルごとにグループ化され、同じテーブルが含まれるクエリでまとめられます。
例 $ pt-query-digest --group-by tables slow-query.log
- order-by
指定された項目の条件に基づいてクエリレポートの表示順を決定します。
例えば、クエリの実行時間の合計で表示したい場合は、Query_time:sumのように指定します。
sum以外にも以下のような指定が可能となっています。
詳細はこちらのリファレンスを参照してください。
| 設定値 | 説明 |
|---|---|
| sum | 項目値の合計値 |
| min | 項目値の最小値 |
| max | 項目値の最大値 |
| cnt | 出力回数 |
例 $ pt-query-digest query slow-query.log --order-by Query_time:sum
- output
出力形式を指定します。
| 設定値 | 説明 |
|---|---|
| report | テキストレポート形式 |
| slowlog | スロークエリログ形式 |
| secure-slowlog | セキュアスロークエリログ形式 |
| json | JSONレポート形式 |
| json-anon | セキュアJSONレポート形式 |
例 $ pt-query-digest --output json slow-query.log
出力結果から発生回数を確認する
以下は、とあるスロークエリログから2024年1月1日から2024年1月8日までを対象として出力したレポートです。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
$ pt-query-digest --since="2024-01-01" --until="2024-01-08" slow-query.log ----- 省略 ----- # 19.6s user time, 200ms system time, 60.39M rss, 123.43M vsz # Current date: Mon Jan 8 00:00:00 2024 # Hostname: aaa # Files: slow-query.log # Overall: 55.95k total, 31 unique, 0.02 QPS, 0.07x concurrency __________ # Time range: 2024-01-01T00:00:00 to 2024-01-07T23:59:59 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= ----- 省略 ----- # Profile # Rank Query ID Response time Calls R/Call # ==== =================================== ================ ===== ======= # 1 0x1ABC4J78MNOPQR345E234HI123N0QR34 128307.2579 6... 10194 12.5865 0.04 SELECT AAA # 2 0x2DEF5K90STUVWX678F567JK456O1ST56 52075.0181 26.9% 43002 1.2110 0.01 SELECT BBB # 3 0x3GHI6L12YZABCD901G890LM789P2UV78 8702.6664 4.5% 2180 3.9920 1.76 SELECT CCC ----- 省略 ----- 以下より Rank 順に各 Query ID の詳細が記載されている # Query 1: 0.03 QPS, 0.35x concurrency, ID 0x1ABC4J78MNOPQR345E234HI123N0QR34 at byte 30118 # This item is included in the report because it matches --limit. # Scores: V/M = 0.04 # Time range: 2024-01-01T00:00:00 to 2024-01-07T23:59:59 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= ----- 省略 ----- # Query 2 # Query 3 ... |
指定した期間の件数を確認するには、出力結果の # Profile の箇所を見ます。
- Query ID
Percona Toolkit がクエリを識別するために付与する一意な識別子。 - Calls
発生回数。
Rank1の 0x1ABC4J78MNOPQR345E234HI123N0QR34 の発生回数が 10194 回であることがわかります。
ここから Rank1 (0x1ABC4J78MNOPQR345E234HI123N0QR34) の1日ごとの発生回数を確認する作業に入ります。
系列レポートのTSV化
以下、弊社ブログの「系列レポートのTSV化」の部分を参考に awk スクリプトを作成します。
コマンドを実行し、ファイルに出力します。
|
1 |
$ pt-query-digest --group-by fingerprint --timeline --no-report slow-query.log | ./query_timeline_to_tsv.awk | sort > slow-query-report.log |
出力したファイルを確認します。
|
1 2 3 4 5 6 7 8 |
$ cat slow-query-report.log 2024-01-01 00:01:00 1ABC4J78MNOPQR345E234HI123N0QR34 1 2024-01-01 00:10:00 2DEF5K90STUVWX678F567JK456O1ST56 3 2024-01-01 00:11:00 3GHI6L12YZABCD901G890LM789P2UV78 5 ----- 省略 ----- ※ awkスクリプトで出力を行うと、Query ID の先頭の「0x」が付与されません。 |
これで秒単位でどのクエリが何回発生したか確認することができます。
しかし、毎秒スロークエリが発生していた場合、1日分を確認するだけで何万行にもなってしまうため、日付ごとのグループ化を行います。
1日ごとにグループ化して発生回数を集計する
先ほど作成した slow-query-report.log に awk コマンドなどを使用して Rank1 (0x1ABC4J78MNOPQR345E234HI123N0QR34) のスロークエリ発生回数を1日ごとにグループ化を行い集計します。
|
1 2 3 4 5 6 7 8 9 |
$ cat slow-query-report.log | grep 1ABC4J78MNOPQR345E234HI123N0QR34 | awk '{a[$1]+=$4} END{for(k in a)print k, " ", a[k];}' | sort 2024-01-01 788 2024-01-02 345 2024-01-03 354 2024-01-04 677 2024-01-05 887 2024-01-06 322 2024-01-07 780 |
出力結果から、1日あたりの発生回数が確認できるようになりました。
awk コマンドの説明
- $1 = 日付
- $2 = 時間
- $4 = 発生回数
{a[$1]+=$4} の部分で、同じ日付の組み合わせが出現するたびその発生回数が集計されるように処理しています。
END{for(k in a)print k, " ", a[k];} の部分で、日付ごとに集計された発生回数を各行に出力しています。
1時間ごとにグループ化して発生回数を集計する
先ほどと同様、awk コマンド を使用して Rank1 (0x1ABC4J78MNOPQR345E234HI123N0QR34) のスロークエリ発生回数を1時間ごとにグループ化を行い集計します。
|
1 2 3 4 5 6 7 8 9 10 11 |
$ cat slow-query-report.log | cut -c 1-13,20- | grep 1ABC4J78MNOPQR345E234HI123N0QR34 | awk '{a[$1, $2]+=$4} END{for(k in a)print k, " ", a[k];}' | sort 2024-01-01 00 25 2024-01-01 01 57 2024-01-01 02 103 2024-01-01 04 58 2024-01-01 07 149 2024-01-01 08 294 2024-01-01 10 171 2024-01-01 11 126 2024-01-01 12 60 ... |
出力結果から、1時間あたりの発生回数が確認できるようになりました。
awk コマンドの説明
- $1 = 日付
- $2 = 時間
- $4 = 発生回数
{a[$1, $2]+=$4} の部分で、同じ日付と時間の組み合わせが出現するたびその発生回数が集計されるように処理しています。
END{for(k in a)print k, " ", a[k];} の部分で、日付と時間の組み合わせごとに集計された発生回数を各行に出力しています。
まとめ
グループ集計することで1か月のうちどのタイミングでスロークエリが発生しやすいのか、そのうちの何時頃がピークなのかといった傾向を知ることができます。
上記の方法は出力行数が増えれば増えるほど見づらくなってしまうため、その場合は awk スクリプトを作成したブログ(pt-query-digest と Metabase でスロークエリログを可視化してみる)より、グラフで可視化することができます。
以上がスロークエリの発生回数をグループ集計する方法でした。
