テクニカルソリューションアーキテクトの笹川です。
本記事ではRDS MySQL使用時のPerformance Insightsの使い方についてご紹介させて頂きます。
Performance Insightsを聞いたことがあるけれど何ができるのか分からない、実際にどのように活用すれば良いのかイメージができないという方もいらっしゃるのではないでしょうか。今回は初めてのPerformance Insights入門と題してサンプルのクエリを実行しながらPerformance Insightsの使い方をご紹介していきます。
Performance InsightsとPerformance Schema
Performance InsightsではDBの負荷状況がMySQLにログインすることなくAWSコンソール上で確認できます。さらにMySQL/MariaDBで提供されているPerformance Schemaを有効にするとより詳細な待機イベント毎に分類されたDBの負荷状況が表示されるようになります。Performance SchemaはRDS作成時にPerformance Insightsを有効にして作成すると自動的に有効になります。詳しくはこちらをご覧下さい。
Performance SchemaとはMySQL5.5.3から導入されたストレージエンジンであり、パフォーマンスをモニタリングする上で必要な情報が格納されています。MySQL5.6.6以降ではデフォルトでONになり、より詳細な待機イベントが記録されるようになりました。
待機イベント
待機イベントとはデータベースで操作を行った際にCPU、ディスクへのI/O、ソケットへのI/Oなど待機が発生するイベントについてクエリやトランザクション単位などで詳細に記録したものです。Performance Insightsを使用するとこの待機イベントをAWSコンソール上で簡単に確認することができるようになります。MySQLの待機イベントに関してはこちらにある程度記載があります。こちらのドキュメントを確認しながら、Performance Insightsで待機イベントがどのように確認できるのか見ていきましょう。
環境とテストデータ
今回はRDSでMySQL8.0.20, インスタンスタイプにdb.m6g.largeを使用して検証していきます。尚、待機イベントの表れ方はDBエンジン毎に異なり、バージョン間でも差異があります。また、Aurora MySQLとRDS MySQLでも異なる場合があるので今回の検証の結果がそのままAurora MySQLでも出力される訳ではないのでご注意下さい。インスタンスタイプも結果に大きく影響してくるため、その点もご注意下さい。
サンプルデータとしてMySQL 公式のものを使用して検証します。
https://github.com/datacharmer/test_db
上記リポジトリをダウンロードし、リポジトリのディレクトリに移動します。
ディレクトリ内のemployees.sqlを下記のように実行してサンプルデータをロードします。
パスワードが聞かれるので入力して下さい。
mysql -hRDSホスト名 -uユーザ名 -p < employees.sql
下記のような実行ログが出力されて終了します。
今回はデータのロードに32秒かかりました。これによりemployees データベースが作られ、
employeesやdept_emp等のテーブルが作成されテストデータも作られています。
INFO
CREATING DATABASE STRUCTURE
INFO
storage engine: InnoDB
INFO
LOADING departments
INFO
LOADING employees
INFO
LOADING dept_emp
INFO
LOADING dept_manager
INFO
LOADING titles
INFO
LOADING salaries
data_load_time_diff
00:00:32
Database load
早速データをロードした時の様子をPerformance Insightsで確認してみましょう。Database loadのグラフで確認してみると、データのロードによってwait/io/file/sql/binlog, wait/io/table/sql/handlerの待機イベントが発生していることが分かります。ドキュメントを元にイベントの意味を確認してみるとディスクへのバイナリログファイル書き出しの待機イベント、テーブルへのI/O待機イベントが発生していることが分かります。MySQLはテーブル作成操作やテーブルデータへの変更イベントをバイナリログとして残すので期待通りのイベントが発生し記録されていることが見て取れます。また大量のデータをテーブルに対してINSERTしている為テーブルへの書き込み待機イベントが発生していることも期待通りと言えます。wait/io/file/sql/io_cache等のドキュメントに記載がない待機イベントについては今回は詳しく見ていきませんが、公式ドキュメントの待機イベント命名規則のページにある程度解説があります。気になる方は是非詳細を確認してみて下さい。次にTop Waitsタブを確認してみましょう。
Top Waits
Top Waitsタブではデータベース負荷に貢献している上位の待機イベントを確認することができます。 Top Waitsタブを確認すると発生した待機イベントの内、最も大きな割合を占めていたのはCPUだったことがわかります。次にテーブルI/O待ち(wait/io/table/sql/handler)、その次にバイナリログの書き込み待ち(wait/io/file/sql/binlog)となっています。Top SQLタブを確認して具体的にどのクエリが待機イベントを発生させていたかを見てみましょう。
Top SQL
Top SQLタブではデータベース負荷に貢献している上位のSQLを確認することができます。Top SQLタブを確認するとsalariesテーブルへのINSERT時に多く待機イベントが発生していることがわかりました。横の+ボタンを押して、より掘り下げて見てみます。
大量にデータがINSERTされている中でバイナリログの書き込み待ち(wait/io/file/sql/binlog)、テーブルの書き込み待ち(wait/io/table/sql/handler)、CPU待ち(CPU)だったりと同じINSERTでもデータによって発生している待機イベントが異なっていることが分かります。今回はどの処理もかかっている時間は短く全体としても大きな時間はかかっていませんが、個々の処理の待ちがより大きくなり積み重なっていくと問題となって現れてきます。問題が発生した時の原因を探す手がかりとしてどのクエリにどういった待機イベントが発生しているのか確認できるのは改善のための有意義な情報となります。
参照系クエリで検証
次はわざと負荷のかかる参照系のクエリを実行してどういった待機イベントが発生するか確認してみましょう。先ほどロードしたemployeesサンプルデータを確認すると、employeesテーブル, dept_empテーブル, departmentsテーブル, salariesテーブル, titlesテーブルがあることが分かります。これらのテーブルから従業員の指名,所属部門,給与,役職名を表示してみましょう。下記のクエリを実行します。
(※DBに負荷がかかり大量のデータが表示されるので、DBリソースに余裕がない場合はご注意ください)
select
a.emp_no,
a.first_name,
a.last_name,
b.dept_no,
c.dept_name,
d.salary,
d.from_date,
d.to_date,
e.title
from employees a
inner join dept_emp b on a.emp_no = b.emp_no
inner join departments c on b.dept_no = c.dept_no
inner join salaries d on a.emp_no = d.emp_no
inner join titles e on a.emp_no = e.emp_no;
+--------+------------+-----------+---------+-------------+--------+------------+------------+-----------------+
| emp_no | first_name | last_name | dept_no | dept_name | salary | from_date | to_date | title |
+--------+------------+-----------+---------+-------------+--------+------------+------------+-----------------+
| 10001 | Georgi | Facello | d005 | Development | 60117 | 1986-06-26 | 1987-06-26 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 62102 | 1987-06-26 | 1988-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 66074 | 1988-06-25 | 1989-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 66596 | 1989-06-25 | 1990-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 66961 | 1990-06-25 | 1991-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 71046 | 1991-06-25 | 1992-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 74333 | 1992-06-24 | 1993-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 75286 | 1993-06-24 | 1994-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 75994 | 1994-06-24 | 1995-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 76884 | 1995-06-24 | 1996-06-23 | Senior Engineer |
+--------+------------+-----------+---------+-------------+--------+------------+------------+-----------------+
...
5124191 rows in set (5.95 sec)
500万ものレコードが取得され、表示されました。全体として約6秒も時間がかかっています。
Performance Insightsを確認します。
Counter Metricsを確認すると行読み込みの平均が大きく跳ね上がっていることが分かります。Database load、Top SQLを確認すると待機イベントもwait/io/table/sql/handlerが全体として大きく影響していることがわかります。5つもテーブルを結合した上で全てのデータを取得しているので、大量のテーブルへの読み込みが発生し、待機イベントが発生していることが想像できます。これだけ大きなデータを頻繁に取るというケースは分析目的でデータベースを使用している場合はあるかもしれませんが、実際は従業員IDを絞るなどした上で取得することが多いと思います。従業員IDを指定してクエリを実行してみます。
select
a.emp_no,
a.first_name,
a.last_name,
b.dept_no,
c.dept_name,
d.salary,
d.from_date,
d.to_date,
e.title
from employees a
inner join dept_emp b on a.emp_no = b.emp_no
inner join departments c on b.dept_no = c.dept_no
inner join salaries d on a.emp_no = d.emp_no
inner join titles e on a.emp_no = e.emp_no
where a.emp_no = 10001;
+--------+------------+-----------+---------+-------------+--------+------------+------------+-----------------+
| emp_no | first_name | last_name | dept_no | dept_name | salary | from_date | to_date | title |
+--------+------------+-----------+---------+-------------+--------+------------+------------+-----------------+
| 10001 | Georgi | Facello | d005 | Development | 60117 | 1986-06-26 | 1987-06-26 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 62102 | 1987-06-26 | 1988-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 66074 | 1988-06-25 | 1989-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 66596 | 1989-06-25 | 1990-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 66961 | 1990-06-25 | 1991-06-25 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 71046 | 1991-06-25 | 1992-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 74333 | 1992-06-24 | 1993-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 75286 | 1993-06-24 | 1994-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 75994 | 1994-06-24 | 1995-06-24 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 76884 | 1995-06-24 | 1996-06-23 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 80013 | 1996-06-23 | 1997-06-23 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 81025 | 1997-06-23 | 1998-06-23 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 81097 | 1998-06-23 | 1999-06-23 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 84917 | 1999-06-23 | 2000-06-22 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 85112 | 2000-06-22 | 2001-06-22 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 85097 | 2001-06-22 | 2002-06-22 | Senior Engineer |
| 10001 | Georgi | Facello | d005 | Development | 88958 | 2002-06-22 | 9999-01-01 | Senior Engineer |
+--------+------------+-----------+---------+-------------+--------+------------+------------+-----------------+
17 rows in set (0.00 sec)
今度はすぐに実行が終了しました。Performance Insightsを確認しても待機イベントは表示されていません。単純な例ですが、Primary Key等を指定してデータを絞り込むことがどれだけ有効か確認できたと思います。今回のサンプルデータでは給与情報が時期によって変動している為、同じ従業員情報でも複数行表示されていることが確認できます。場合によっては範囲を指定して最新のデータだけに絞り込んで取得ということも要件によっては考えられるでしょう。その際もPerformance Insightsを見ながら待機イベントが発生しているか確認し、効率の良いクエリになっているか確かめながら作業していくことができます。
wait/io/table/sql/handlerについて
wait/io/table/sql/handlerが書き込み時にも読み込み時にも表示されていることにお気づきになりましたでしょうか。実はMySQLではテーブルへの書き込みも読み込みも同じwait/io/table/sql/handler待機イベントとして現れる為、書き込みと読み込みどちらで待機しているのか詳細を確認する必要があります。そういった意味でも、Performance Insights上で待機イベント毎のクエリを確認できるのは非常に有意義となります。
尚、DBエンジンによっては書き込みと読み込みを別のイベントとして記録するものもある為、詳細はお使いのDBエンジンのドキュメントをご確認下さい。
まとめ
今回は簡単な例を使ってPerformance Insightsのご紹介を致しました。実際のチューニング時は今回のような単純なものではなく複雑なパターンとなってくる為、より詳細にDBの状態を確認する必要が出てきます。そういった時にもPerformance Insightsで確認できる情報は有意義な手掛かりとなってくるので是非実際の業務にお役立て下さい。
Performance Insightsはデフォルトで1週間分の履歴データを保存し最長で2年分の履歴データを保存することができます。こちらの料金ページにて詳細が記載されているので合わせてご参照下さい。
