はじめに

MySQLでは、たびたびスロークエリがパフォーマンス上の問題になることがあります。
Percona Monitoring and Management(以下PMM)では様々なメトリクスが収集されており、スロークエリの問題を対処するためのグラフが用意されています。

例えば、MySQL Instance SummaryダッシュボードのMySQL Slow Queriesパネルではスロークエリの発生回数を確認できます。

また、Query Analyticsダッシュボードでは、様々な観点からスロークエリの分析が可能です。

一方で、MySQL Slow Queriesはスロークエリの発生回数のグラフであり、各スロークエリがどのくらいの実行時間であったかは示しません。
また、Query Analyticsは長期間のスロークエリを総合的に分析するのにはとても強力なツールですが、リアルタイムでクエリをモニタリングするのには向いていません。

本記事では、PMMがデフォルトでMySQLのスロークエリログから収集している情報から、スロークエリのなかでも更に長いクエリをモニタリングする方法を紹介します。

前提

今回は PMM 2.38.0, MySQL8.0.33を使用しています。
また、PMM ClientはMySQLのスロークエリを情報を収集する場合、スロークエリログとパフォーマンススキーマのどちらから収集するかを選択できます。
今回の検証ではスロークエリログから収集しています。

ClickHouseについて

PMM Serverは複数のツールが組み合わさってできています。収集されたOSやDBの統計情報はVictoriaMetricsに、スロークエリの情報はClickHouseに保存されます。
今回はこのClickHouseに保存されているデータを使用します。詳しくは公式ドキュメントのArchitectureをご参照ください。

スロークエリログから収集されたデータはClickHouseのpmmデータベースのmetricsテーブルに格納されます。まずはこのテーブル定義を確かめてみましょう。

ExploreでData sourceをClickHouseにすることで、ClickHouseにクエリができます。

Query TypeをSQL Editor、FormatをTableにして、desc pmm.metricsを実行すると、図のようにカラム定義を確認できます。

収集されたスロークエリの情報は同じクエリ、時間帯ごとにまとめられて、pmm.metricsに保存されます。

今回、注目するのはperiod_start,m_query_time_max,num_queriesです。

• period_start: 時間帯。これは１分間隔で分類されます
• m_query_time_*: クエリの実行時間の統計。sum,min,max,p99などがあります。
  • 今回はm_query_time_maxを使用します。これは、同じ時間帯に実行された同一クエリの中で最大実行時間です。
• num_queries：その時間帯に実行された回数

例えば、以下の図はClickHouseでpmm.metricsに対して以下のクエリを実行した結果です。
MySQLでは同じ時間帯に同じクエリを実行しています。

num_queriesから2023-07-05 09:46:00には5回同じクエリを実行していることがわかります。また、この5回のうち最大実行時間はm_query_time_maxから0.869秒だとわかります。
一方、pmm.metricsで確認できる実行時間は統計情報なので、各クエリのそれぞれ個別の実行時間はわかりません。
これは、pmm.metricsに保存される時点で、実行時間などクエリの個々の情報は一部失われることを意味します。
もし個々に確認したい場合は直接スロークエリログを確認する必要があります。

pmm.metricsのカラムについて

pmm.metricsは200カラムを超えるため、今回は全ての紹介はしません。
また、MySQLの他にPostgreSQLとMongoDBで収集したデータも全て同じpmm.metricsテーブルに保存します。
そのため、PostgreSQLとMongoDBでしか使用されないカラムもあります。

今回はMySQLのスロークエリログからデータを収集した場合に使用できる主なカラムを紹介します。

カラム名	説明
schema	クエリに関係するスキーマ
username	クエリを実行したユーザ
client_host	クライアントのIPアドレスorホスト名
example	クエリの例。データ部分はマスクされていません 例: SELECT * from d1.t1 where id = 1
fingerprint	クエリのフィンガープリント。データ部分が?となっています 例: SELECT * from d1.t1 where id = ?
m_lock_time_*	ロックを取得するまでにかかった時間 m_query_time_cnt: 回数 m_query_time_sum: 合計時間 m_query_time_min: 最小時間 m_query_time_max: 最大時間 m_query_time_p99: 99パーセンタイル
m_rows_sent_*	クライアントに送信した行数 m_rows_sent_cnt: 回数 m_rows_sent_sum: 合計行数 m_rows_sent_min: 最小行数 m_rows_sent_max: 最大行数 m_rows_sent_p99: 99パーセンタイル
m_rows_examined_*	scanした行数 m_rows_examined_cnt: 回数 m_rows_examined_sum: 合計行数 m_rows_examined_min: 最小行数 m_rows_examined_max: 最大行数 m_rows_examined_p99: 99パーセンタイル

スロークエリをモニタリングする

まずは、実行時間が長い順に並べたリストを作成してみます。

新規のダッシュボードを作成し、Add Panel -> Add a new panel を選択します。

VisualizationをTableにして、Data sourceをClickHouseにします。
Query TypeはSQL EditorまたはQuery Builderを選択できます。

• SQL Editor: 直接SQLを記述することができます。
• Query Builder: 各項目をプルダウンから選択していくことで自動でSQLを生成することができます。

今回はQuery Builderを使用してみます。

その他設定内容は以下の通りです。

• スロークエリが発生した時間(period_start)、最大実行時間(m_query_time_max)、クエリ(example)を表示
• 最大実行時間で降順にソートし、上位100件を表示
• service_name=mysql-1という条件で特定のMySQLのスロークエリのみを表示

また、Filtersで設定してある、period_start WITHIN DASHBOARD TIME RANGEは時間範囲をダッシュボードで指定した時間範囲に合わせるためのものです。

このとき、以下のクエリが生成されます。

続いて1分ごとのクエリの最大値を取ってグラフにしてみます。
max()関数を使用するために今回はSQL Editorで直接クエリを書いていきます。
VisualizationをTime seriesにして、以下のようなクエリを入力します。

period_start ごとのm_query_time_maxの最大値をSELECTしています。すると以下のようなグラフが表示されます。

次は、特定の秒数を超えたスロークエリの数を示すグラフを作成してみます。
これは、例えば、「long_query_timeでは1.0秒に設定しているが、サービスとして10秒を超えるクエリが発生していないかも合わせて確認したい。」という場合などで役に立つかと思います。
今回もSQL Editorで以下クエリを直接書きます。

WHERE句の条件でAND m_query_time_max > [閾値]とすることでその秒数を超えたクエリの数を表示することができます。

ただし、"ClickHouseについて"で説明した通り、同じ時間帯に実行された同じクエリの個々の実行時間の情報は保存されていません。
そのため、このクエリでは、同じクエリが同じ時間帯で2回以上実行されていた場合は、何回実行されていても1回分とカウントされます。
よって、実際にn秒を超えたクエリの数より、値が小さくなる可能性があります。

アラートを設定する

ClickHouseをデータソースとしてアラートを設定することができます。
今回は10秒を超えたクエリが1回発生したらアラートをトリガーします。

まず、New alert ruleからアラートを作成します。

ClickHouseをデータソースとしたい場合は、Percona templated alertsではなく、Grafana managed alertsを選択する必要があるようです。
データソースをClickHouseにして、クエリを記載します。今回使用するのは以下のクエリです。

また、ConditionsでWHEN max() OF A IS ABOVE 1としてこのクエリの結果の最大値が1以上の場合、アラートをトリガーするようにします。

アラート名等は適当に設定し、SAVE and exitボタンを押します。

10秒以上のスロークエリを発生させた後、Fired alertsタブを確認するとアラートとなっていることがわかります。

まとめ

クエリの実行時間についてPMMで監視する方法を紹介しました。今回紹介した方法は、追加のデータ収集などは行わずに既に収集されている情報を表示しているため、気軽に試すことができるかと思います。
また、説明の簡略化のためにpmm.metricsの一部のカラムしか使用しませんでしたが、他にも利用できるカラムは多くあります。
例えば、where username != 'bat_user'として、バッチ処理用のユーザーを除外して、スロークエリをチェックするなど、様々な要件に応じたフィルタリングができそうです。興味のある方は試してみて下さい。