はじめに
MySQL のスロークエリチューニングを行っていると、スロークエリの情報を分析するためにデータを可視化したいというニーズが少なからず発生するのではと思います。
弊社では、スロークエリログの分析ツールとして Percona Toolkit の pt-query-digest を主に使用しています。
pt-query-digest の出力レポート(以降、ダイジェストレポートと呼ぶことにします)では、各クエリごとの詳細レポートが表示されます。
|
1 2 3 4 5 6 7 8 9 10 |
# Query 2: 0.18 QPS, 14.99x concurrency, ID 0x16D09AA9DEAF56844C0A393494B79583 at byte 14384444 # This item is included in the report because it matches --limit. # Scores: V/M = 5.19 # Time range: 2022-04-05T07:03:28 to 2022-04-05T11:38:49 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 1 2968 # Exec time 6 247634s 27s 239s 83s 124s 21s 76s # Lock time 2 10s 53us 4s 3ms 167us 86ms 98us (...) |
たとえば、このスロークエリの発生状況を知りたい場合、以下の情報は読み取ることができます。
Time rangeから、最初と最後に発生した日時の範囲Countから、スロークエリログの総発生回数
ただし、このスロークエリが時間帯ごとに何回発生しているか、発生間隔はどの程度かを知りたい時はこの情報のみでは不明です。
スロークエリとして出現しているが、チューニング対象とすべきか精査したい場合(夜間帯にのみ集中していて、バッチ処理であることを推定したり)や、
長期的な観察視点で、いつ時点から発生したか(またはチューニングや改修により収束したか)を把握したいというケースが想定されます。
MySQL のスロークエリログを可視化するツールとしては、Anemometer(およびyoku0825氏によるラッパーツールanemoeater) が著名です。
GitHub – box/Anemometer: Box SQL Slow Query Monitor
GitHub – yoku0825/anemoeater: Wrapper-script for box/Anemometer
ただ、本家(Anemometer)は開発が止まってしまっている状況であること、また、yoku0825氏が anemoeater で言及している通り、Percona Toolkit 3.0.11 以降の pt-query-digest では動かないという問題があります。
※詳しくはこちらをご一読ください。
特にこれらを気にする必要がなければ、Anemometer を使用する、という選択で問題ありません。
また、昨今では、Datadog や Splank を使ってスロークエリログを(ある程度パースした上で)データ投入し、分析を行っているというユーザも多いのではないかと思います。
本記事では、これからスロークエリの分析を行いたく、まずは可視化を手軽に行ってみたいユーザであったり、他の仕組みを使ってみようと考えているユーザに向けて、pt-query-digest と、OSS の BI ツール Metabase を使った方法を紹介します。
-
※ちなみに、Percona Monitoring and Management 2 (PMM2) であれば、Query Analytics(QAN) という機能が使用可能ですので、細やかなクエリ分析が可能です。
ただし、今回紹介している時系列発生状況はQPSであれば確認できるようですが、細かくドリルダウンすることができないようです。- PMM2 はDemoが公開されていますので、ぜひ一度操作を体感してみてください。
用意する動作環境
今回ご紹介する内容は、Linux OS で以下のソフトウェアがインストール・使用可能であることを前提としています。
- docker, docker-compose
- pt-query-digest
なお、本記事での使用バージョンは以下の通りでした。
|
1 2 3 4 |
docker 20.10.12 docker-compose 1.29.2 pt-query-digest 3.1.0 (※執筆時点の最新バージョンは3.3.1でしたので少し古いバージョンを使っていました) |
pt-query-digest による時系列レポートの出力
ダイジェストレポートでは、デフォルトで fingerprint (リテラルが削除され、ホワイトスペースが折りたたまれた、抽象化されたクエリテキスト) 単位で集約化されます。
ただし、前述の通り発生日時や回数もまとめられてしまうため、その内訳を知ることができません。
そこで、--timeline オプションを使います。
この機能は、入力されたスロークエリログの全エントリを対象に、発生日時と回数を集計して時系列でレポート出力してくれます。
以下は、fingerprint 単位でグルーピングして、時系列レポートのみを別ファイルに出力するコマンド例です。
※ --no-report を付けなければ、ダイジェストレポートの最後尾に時系列レポートが追記されます。
|
1 2 |
$ pt-query-digest --group-by fingerprint --timeline --no-report \ mysql-slow.log > mysql-slow-timeline.txt |
出力内容はこのようになります。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
$ head -3 mysql-slow-timeline.txt; tail mysql-slow-timeline.txt # ######################################################################## # fingerprint report # ######################################################################## # 2022-05-25T16:33:27 0:00 1 select * from t_somedata where insert_at between ? and ? and type=? and version=? and spec=? limit ? # 2022-05-25T16:33:32 00:36 10 select * from dat_send_test where type like coalesce(?,?) and spec like coalesce(?,?) and version like coalesce(?,?) and check_flg like coalesce(?,?) and data_in_time != ? and (data_out_time between ? and ? or data_in_time between ? and ? or (data_out_time <= ? and data_in_time >= ?)) order by data_out_time # 2022-05-25T16:34:10 0:00 1 select * from t_somedata where insert_at between ? and ? and type=? and version=? and spec=? limit ? # 2022-05-25T16:34:12 03:29 44 select * from dat_send_test where type like coalesce(?,?) and spec like coalesce(?,?) and version like coalesce(?,?) and check_flg like coalesce(?,?) and data_in_time != ? and (data_out_time between ? and ? or data_in_time between ? and ? or (data_out_time <= ? and data_in_time >= ?)) order by data_out_time # 2022-05-25T16:37:46 0:00 1 select * from t_somedata where insert_at between ? and ? and type=? and version=? and spec=? limit ? # 2022-05-25T16:37:51 00:02 2 select * from dat_send_test where type like coalesce(?,?) and spec like coalesce(?,?) and version like coalesce(?,?) and check_flg like coalesce(?,?) and data_in_time != ? and (data_out_time between ? and ? or data_in_time between ? and ? or (data_out_time <= ? and data_in_time >= ?)) order by data_out_time # 2022-05-25T16:37:57 0:00 1 select * from t_somedata where insert_at between ? and ? and type=? and version=? and spec=? limit ? # 2022-05-25T16:38:00 21:42:05 4011 select * from dat_send_test where type like coalesce(?,?) and spec like coalesce(?,?) and version like coalesce(?,?) and check_flg like coalesce(?,?) and data_in_time != ? and (data_out_time between ? and ? or data_in_time between ? and ? or (data_out_time <= ? and data_in_time >= ?)) order by data_out_time # 2022-05-26T14:20:06 0:00 1 select * from t_somedata where insert_at between ? and ? and type=? and version=? and spec=? limit ? # 2022-05-26T14:20:15 19:17:43 4663 select * from dat_send_test where type like coalesce(?,?) and spec like coalesce(?,?) and version like coalesce(?,?) and check_flg like coalesce(?,?) and data_in_time != ? and (data_out_time between ? and ? or data_in_time between ? and ? or (data_out_time <= ? and data_in_time >= ?)) order by data_out_time |
タイムスタンプの次のカラムは、そのクエリグループから最初に出現したクエリと最後に出現したクエリの時間差を表しています。
上のサンプルにはありませんが、1+00:00:16 という表現の場合、「前回発生から1日と16秒経過して再度発生した」という意味合いになります。
その隣のカラムは発生回数を表しています。
この時点で、時系列レポートを csv や tsv に編集し直して、Excel や スプレッドシートといったソフトウェアにインポートして、ピボットテーブル/グラフでデータ分析してしまっても、それはそれでありだと思います。(一過性の問題対応時など)
ただし、スロークエリログの入力量が多かったり、日々の運用プロセスにおいて継続的な確認を行っていきたい場合は、データベースでのデータ管理と BI ツールでデータ可視化を効率よく行っていきたいニーズは高まると思いますし、チームや組織といった関係者間での共有も容易になるメリットがありますので、そうしたほうがおすすめです。
時系列レポートのTSV化
ここでもうひと手間、後述する DB(MySQL) へのデータロード用に、先ほどの時系列レポートデータを TSV 化する awk スクリプトを作成しておきましょう。
以下のコードを query_timeline_to_tsv.awk というファイル名で保存し、実行権限を付与しておきます。
|
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 |
#!/usr/bin/awk -f BEGIN { OFS="\t"; }; NR>3 { { # Assign the query fingerprint to a variable query=""; for(i=5;i<NF;++i){ query=query $i " "; } query=query $NF; gsub("T"," ",$2); } { # Convert fingerprint to MD5 checksum hash=""; cmd="echo -n \047"query"\047 | md5sum"; checksum=((cmd | getline line) > 0 ? line : "FAILED"); close(cmd); sub(/ .*/,"",checksum); } print $2,toupper(checksum),$4 } |
|
1 |
$ chmod u+x query_timeline_to_tsv.awk |
この awk スクリプトを先ほどの時系列レポートに噛ませ、最後にタイムスタンプでソートします。
|
1 2 |
$ pt-query-digest --group-by fingerprint --timeline --no-report mysql-slow.log | \ ./query_timeline_to_tsv.awk | sort | tail |
このスクリプトのポイントは、クエリの fingerprint を MD5 チェックサム値に変換して出力しているところです。
これにより、ダイジェストレポートとの紐付けが容易に行えるようになります。
|
1 2 3 4 5 6 7 8 9 10 |
2022-05-25 16:33:27 749C13DCCDF5866AA2704C413B54ACB0 1 2022-05-25 16:33:32 3AED3F76ADACEC025A558FF515A8FE41 10 2022-05-25 16:34:10 749C13DCCDF5866AA2704C413B54ACB0 1 2022-05-25 16:34:12 3AED3F76ADACEC025A558FF515A8FE41 44 2022-05-25 16:37:46 749C13DCCDF5866AA2704C413B54ACB0 1 2022-05-25 16:37:51 3AED3F76ADACEC025A558FF515A8FE41 2 2022-05-25 16:37:57 749C13DCCDF5866AA2704C413B54ACB0 1 2022-05-25 16:38:00 3AED3F76ADACEC025A558FF515A8FE41 4011 2022-05-26 14:20:06 749C13DCCDF5866AA2704C413B54ACB0 1 2022-05-26 14:20:15 3AED3F76ADACEC025A558FF515A8FE41 4663 |
試しに、ダイジェストレポートをチェックサム値で grep すると、レポート内の各クエリの ID と合致することが確認できます。
|
1 2 3 4 5 6 |
$ pt-query-digest mysql-slow.log > mysql-slow-digest.txt $ grep -A3 749C13DCCDF5866AA2704C413B54ACB0 mysql-slow-digest.txt # Query 25: 0.00 QPS, 0.00x concurrency, ID 0x749C13DCCDF5866AA2704C413B54ACB0 at byte 136053280 # This item is included in the report because it matches --outliers. # Scores: V/M = 10.47 # Time range: 2022-04-12T09:11:59 to 2022-05-26T14:20:06 |
ダイジェストレポートにおけるクエリ ID は 0x が先頭に付与されていますが、これは pt-query-digest がレポート出力時に MD5 チェックサム値に後付けしたものになります。
今回の時系列レポートのほうは、0x を付与しないでそのままの形式で出力しておきます。(理由は後述します)
なお、元の時系列レポートデータに含まれていた「前回発生時からの時間差」データは、今回不要だったため DB にロードする対象外としました。(TSVには含めておいて、LOAD DATA コマンドで対象カラムを落とすのでも構いません)
Metabase + MySQL 環境を Docker で構築する
Metabase についてはこちらもメジャーなソフトウェアですので、説明は割愛させていただきます。
Metabase | Business Intelligence, Dashboards, and Data Visualization
手軽に利用開始できるのが嬉しいですね。
今回は Docker コンテナ版で環境構築してみます。
Metabase Documentation | Running Metabase on Docker
work ディレクトリ配下で docker-compose.yml を作成します。
|
1 2 3 |
$ mkdir -p query-analyze $ cd query-analyze $ vi docker-compose.yml |
以下は docker-compose.yml の設定例です。(簡易的にパスワード等をベタで指定していますのでご注意ください)
|
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 |
version: "3" services: metabase: container_name: "metabase" image: metabase/metabase ports: - "13000:3000" db: container_name: "mysql" image: mysql:8.0 ports: - "13306:3306" volumes: - type: volume source: mysql-data target: /var/lib/mysql - type: bind source: ./init target: /docker-entrypoint-initdb.d command: --default-authentication-plugin=mysql_native_password --local-infile=1 environment: - MYSQL_ROOT_PASSWORD=MySQL8.0 - MYSQL_DATABASE=query_analyze - MYSQL_USER=mb_user - MYSQL_PASSWORD=P@ssw0rd volumes: mysql-data: name: mysql-vol |
注意点としては、MySQL の起動オプションの2つの指定です。
- MySQL 8.0 をデータストアにする場合、Metabase からの接続では
caching_sha2_password認証プラグインは未対応のためエラーになってしまうので、mysql_native_passwordにしておく必要があります。 - 前述の pt-query-digest 時系列レポート(やクエリヒストリなど)をDBにロードするため、
local-infileを有効にしておきます。
それ以外の設定については、お好みに併せて変更いただいて構いません。
Metabase と MySQL コンテナを起動します。
|
1 |
$ docker-compose up -d |
Metabase は以下URLでアクセスできます。(localhostは環境に合わせて適宜変更)
http://localhost:13000/
画面上のガイドに沿って初期設定を済ませておきましょう。(説明は割愛します)
ちなみに、本記事ではローカライゼーションは英語にしています。 (少し違和感がある日本語表記のため)
また、日時表記に関しては、以下のように設定を変更しています。
クエリ分析用テーブルの作成
時系列レポートデータ用のテーブルを作成しておきます。
※スキーマはコンテナ作成時に自動作成済み
|
1 2 3 4 5 6 |
CREATE TABLE IF NOT EXISTS query_analyze.query_timeline ( checksum CHAR(32) NOT NULL, datetime datetime NOT NULL, count int NOT NULL, PRIMARY KEY(checksum, datetime) ); |
|
1 |
$ docker exec -i mysql mysql -umb_user -pP@ssw0rd < query_analyze_timeline.sql |
時系列レポートデータのロード
時系列レポート出力 --> awk スクリプトでチェックサム変換・TSV 化 --> MySQL へデータロード という処理を行っています。
|
1 2 3 4 5 6 7 8 9 10 11 12 |
$ pt-query-digest --group-by fingerprint --timeline --no-report mysql-slow.log | \ ./query_timeline_to_tsv.awk | sort | \ docker exec -i mysql mysql -umb_user -pP@ssw0rd --enable-local-infile -e " LOAD DATA LOCAL INFILE '/dev/stdin' INTO TABLE query_analyze.query_timeline (@datetime, @checksum, @count) SET checksum = @checksum , datetime = @datetime , count = @count ; " |
Metabase でデータを可視化してみる
ここからは Metabase の画面に遷り、ロードしたデータを可視化して眺めてみましょう。
初期設定時に DB への接続設定が済んでいるはずですので、Browse data > query_analyze > Query Timeline と遷移するとデータがテーブル形式で表示されます。
画面下部の Visualization をクリックし、Bar(棒グラフ)を選択してみると、簡単にグラフ化されました。
チェックサムが凡例となっています。ここで凡例上の特定のチェックサムをクリックすると、フィルタされたデータが表示されます。
テーブル形式の状態から、フィルタをかけることも可能です。
他の BI ツールでも備わっているのか、細かい比較はできていませんが、Metabase では細やかなフィルタリング機能が備わっている点が、非常に使いやすくおすすめなポイントです。
たとえば、日中(サービス提供時間帯)のみのデータに絞りたい場合はこのようなフィルタが可能です。
特定の一週間のみのデータに絞ったグラフはこのようになります。
画面右上の + New ボタンから、独自のクエリ(画面操作・SQLなど)を作成し、保存することができます。
クエリ結果は、csv/xlsx/json 形式でダウンロードもできますので、データの2次利用が可能です。
そして、特定のグループでダッシュボードを作成し、クエリ結果のグラフをまとめて表示することで、ユーザが柔軟にカスタマイズできる点は、他の BI ツール同様かと思います。
なによりも、UIの見やすさや操作のしやすさは Metabase を選ぶ大きなポイントではないかと思います。
pt-query-digest のクエリヒストリ, クエリレビューデータDB保存機能を併用する
pt-query-digest には、ダイジェストレポートの出力を DB に保存する機能が備わっています。
Query analysis is a best-practice that should be done frequently. To make this easier, pt-query-digest has two features: query review (–review) and query history (–history). When the –review option is used, all unique queries are saved to a database. When the tool is ran again with –review, queries marked as reviewed in the database are not printed in the report. This highlights new queries that need to be reviewed. When the –history option is used, query metrics (query time, lock time, etc.) for each unique query are saved to database. Each time the tool is ran with –history, the more historical data is saved which can be used to trend and analyze query performance over time.
pt-query-digest | –review
pt-query-digest | –history
この機能を併用して、先ほどロードした時系列レポートデータとダイジェストレポートの分析データを関連付けて更なるデータ分析も可能になります。
ここで、それぞれのテーブルは MD5 チェックサム値で繋げることができます。(時系列レポートデータ側のチェックサム先頭に 0x を付けなかったのはこのためです)
クエリヒストリ、クエリレビューデータの格納テーブルのDDLは以下になります。
|
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 37 38 39 40 41 42 43 |
CREATE TABLE IF NOT EXISTS query_review ( checksum CHAR(32) NOT NULL PRIMARY KEY, fingerprint MEDIUMTEXT NOT NULL, sample MEDIUMTEXT NOT NULL, first_seen DATETIME, last_seen DATETIME, reviewed_by VARCHAR(20), reviewed_on DATETIME, comments TEXT ); CREATE TABLE IF NOT EXISTS query_history ( checksum CHAR(32) NOT NULL, sample MEDIUMTEXT NOT NULL, ts_min DATETIME, ts_max DATETIME, ts_cnt FLOAT, Query_time_sum FLOAT, Query_time_min FLOAT, Query_time_max FLOAT, Query_time_pct_95 FLOAT, Query_time_stddev FLOAT, Query_time_median FLOAT, Lock_time_sum FLOAT, Lock_time_min FLOAT, Lock_time_max FLOAT, Lock_time_pct_95 FLOAT, Lock_time_stddev FLOAT, Lock_time_median FLOAT, Rows_sent_sum FLOAT, Rows_sent_min FLOAT, Rows_sent_max FLOAT, Rows_sent_pct_95 FLOAT, Rows_sent_stddev FLOAT, Rows_sent_median FLOAT, Rows_examined_sum FLOAT, Rows_examined_min FLOAT, Rows_examined_max FLOAT, Rows_examined_pct_95 FLOAT, Rows_examined_stddev FLOAT, Rows_examined_median FLOAT, PRIMARY KEY(checksum, ts_min, ts_max) ); |
マニュアル を見ていただくと気付くかと思いますが、Percona Server for MySQL を使用する場合、スロークエリログ拡張が実装されているため、より多くの Attribute と Metrics データを格納することが可能です。
— Percona extended slowlog attributes
— http://www.percona.com/docs/wiki/patches:slow_extended
Percona Server for MySQL 8.0 のスロークエリログ拡張について詳細は以下のドキュメントをご参照ください。
また、fingerprint と sample のデータ型を TEXT(マニュアルデフォルト) から MEDIUMTEXT に変更していますが、長大なクエリを格納する場合に文字列長不足によるインポートエラーを回避するためです。
横道に逸れてしまいましたが、先ほどの DDL を実行してテーブルを作成します。
|
1 |
$ docker exec -i mysql mysql -umb_user -pP@ssw0rd query_analyze < query_review_history.sql |
クエリヒストリ、レビューのテーブルへデータをロードするコマンドは以下のようになります。
(同時にダイジェストレポートも作成可能です)
|
1 2 3 4 |
$ pt-query-digest \ --review D=query_analyze,u=mb_user,p=P@ssw0rd,h=127.0.0.1,P=13306 \ --history D=query_analyze,u=mb_user,p=P@ssw0rd,h=127.0.0.1,P=13306 \ mysql-slow.log > mysql-slow-digest.txt |
Metabase に反映されない場合は、データベース設定画面から Sync database schema now ボタンをクリックして同期してみましょう。
無事、Query History と Query Review が追加されました。
Query History を覗いてみると、ダイジェストレポートで出力されるデータと同一の内容が格納されていることが確認できます。
自動探索機能 (X-rays)
今回使用(pull)した Metabase は v0.43 (Latest) ですが、データの自動探索 (X-rays) という機能が実装されていました。
Metabase Documentation | 14 X Rays
X-rays are a fast and easy way to get automatic insights and explorations of your data.
Welcome 画面のイナズマアイコンの箇所をクリックしてみます。
すると、テーブルに格納されたデータを元に、Metabase が自動でデータ集約して作成されたグラフが纏まったページに遷移しました。
タイムスタンプフィールドに焦点を当てた X-rays はこちらのように作成されました。
まさに今回求めていたスロークエリの時系列発生状況をサマライズしてくれています。(日毎、曜日毎など)
BI ツールが未経験だったり、どのようにデータを可視化すればわからないといった不安があるユーザも、まずはこの機能を使って触り始めるには良いのではと思いました。
おわりに
後半はほとんど Metabase の紹介になってしまいましたが、pt-query-digest と docker が使用できる環境があれば、手軽にスロークエリの可視化が行えます。
また、もし SHOW GLOBAL STATUS の定期的なデータもあるようでしたら、併せて Metabase でデータ可視化することで、スロークエリとの相関関係を調査したり、といった活用方法も考えられます。
(既に MySQL の監視を行っている場合は冗長かもしれませんが)
データの分析方法はユーザ次第ですが、スロークエリチューニング活動における精査がより効率的に行え、さらに新しい洞察が得られるかもしれません。
興味がありましたらぜひ一度お試しください。
