freeeの開発情報ポータルサイト

トップ > Advent Calendar 2022 > Performance Schemaの仕組みと活用法の紹介

Performance Schemaの仕組みと活用法の紹介

Advent Calendar 2022 SRE ピックアップ

メリークリスマス！！freee Developers Advent Calendar 2022 25日目担当のid:shallow1729です！昨日はtdtdsさんでfreee特有の風土病：エンジニアの症例と寛解についてでした！ 僕からはMySQLのPerformance Schemaという機能の仕組みの解説とfreeeでの活用についての紹介をします。

前置き

Performance SchemaはMySQLで実行されるトランザクションやクエリなどの実行時の様々な情報を取得してくれる機能です。特に面白いのは後で説明するようにstageやwaitなどのMySQLの実装レベルでのモニタリングを提供してくれているところで、これを使う事でどのあたりがボトルネックになっているかについて実際のProduction環境のワークロードで分析できる点です。また、最近だと例えばAWSのRDSを用いているとPerformance InsightsというPerformance Schemaをサンプリングして描画してくれるツールがあったりとMySQLのコアなユーザーでなくても目にする機会があると思っています。そこで今回はPerformance Schemaで得られた情報を自力で分析できるように、これがどのような仕組みで動いているかの解説をしようと思います。なお、この記事ではMySQL8.0.31をベースに解説します。

Performance Schemaを使ってみる

まずは詳細な説明の前にざっくりと使ってみてどういうものか確認してみましょう。 とりあえずPerformance Schemaの有効化はperformance_schemaというvariablesで制御できます。 ですが、Performance Schemaでどのような情報を取るかはperformance_schemaデータベースのperformance_schema.setup_instrumentsとperformance_schema.setup_consumersというテーブルで管理されています。performance_schema.setup_instrumentsのテーブルのレコードは以下のようになっています。

mysql> select NAME, ENABLED, TIMED from performance_schema.setup_instruments\G;
*************************** 742. row ***************************
NAME: statement/abstract/new_packet
ENABLED: NO
TIMED: NULL
*************************** 743. row ***************************
NAME: statement/abstract/relay_log
ENABLED: NO
TIMED: NULL
*************************** 744. row ***************************
NAME: transaction
ENABLED: NO
TIMED: NULL
*************************** 745. row ***************************

...
*************************** 1246. row ***************************
NAME: memory/sql/servers_cache
ENABLED: YES
TIMED: NULL
*************************** 1247. row ***************************
NAME: memory/sql/Relay_log_info::mta_coor
ENABLED: YES
TIMED: NULL
*************************** 1248. row ***************************

まずNAMEカラムに注目するとmemory/から始まる項目はメモリの使われ方に関する情報が得られるんだろうなとか、transactionはトランザクションの情報が得られるんだろうなというイメージが湧くと思います。これらのレコードについてENABLEDがYESになっていると、そのレコードに対応するイベントの情報がperformance_schemaデータベースのテーブルに保管されるようになります。TIMEDがYESだと時間の計測も行います。逆にNOにすれば情報を取得しなくなるので、再起動無しにMySQL内部の情報についてモニターする項目を変更することができます。

Performance Schemaは様々な情報を提供してくれますが、今回はこれらの中でもクエリの実行時の内部情報の取得に役立つstageやwaitというものにフォーカスします。ざっくりとはstageはoptimizationなどのクエリ実行の中のステージのどこにいるのかという情報を、waitはさらにその中でも特定のIOイベントやlatchの取得などのイベントの情報を教えてくれるものです。

stageの情報を取得できるようにしたい場合は以下のようなクエリを実行します。

mysql> update performance_schema.setup_consumers set ENABLED="YES" where NAME like "%stage%";
mysql> update performance_schema.setup_instruments set ENABLED="YES", TIMED="YES" where NAME like "stage%";

有効にしたあと雑にクエリを実行してperformance_schema.events_stages_historyテーブルを確認してみます。

mysql> select * from test.sample\G; # 有効なクエリならなんでもいい
*************************** 1. row ***************************
  id: 1
name: test

mysql> select EVENT_NAME, SOURCE, TIMER_WAIT from performance_schema.events_stages_history\G;
*************************** 1. row ***************************
EVENT_NAME: stage/sql/starting
    SOURCE: init_net_server_extension.cc:103
TIMER_WAIT: 685432000
*************************** 2. row ***************************
EVENT_NAME: stage/sql/checking permissions
    SOURCE: sql_authorization.cc:2147
TIMER_WAIT: 61637000
*************************** 3. row ***************************
EVENT_NAME: stage/sql/Opening tables
    SOURCE: sql_base.cc:5796
TIMER_WAIT: 1942809000
...

このようにevent_stages_historyテーブルからはクエリ実行の各stageにどれくらい時間がかかったかなどの情報が取得できます。SOURCEカラムがあるようにこれらで得られる情報はコード中でprintデバッグしてるようなイメージに近いもので、リコンパイルも再起動も無しにモニタリングする場所を変更できるのがPerformance Schemaの特徴です。

Peroformance Schemaのざっくりとした構成

先ほどの例でなんとなくPerformance Schemaがどういうものかの具体的なイメージはついたかと思いますが、改めて解説します。

  • Perforamcne Schemaでどの情報を取得するかの管理や得られた情報の閲覧はperformamce_schemaデータベースで行う事ができます。
  • 実装レベルではperformance_schemaデータベースは専用のストレージエンジン(storage/perfschema)を用いており、データは永続化されません
  • Performance Schemaの視点ではトランザクションの実行はtransaction, statement, stage, waitという順で階層構造(event hierarchy)を取っていると見なされます。
├ transaction
　└ statement
　　　└ stage
　　　　└ wait
  • Performance Schemaの一つ一つのstageやwaitはソースコードに対応する箇所があります。
    • waitの場合は例えばlockの取得はさまざまな場所で同じlockを取る事があるのでどの場所で取られたかはSOURCEを確認する必要がありそうです。

ここまででPerformance Schemaについての大まかな解説をしましたが、実際にstageやwaitのような情報を解釈して意思決定に繋げるには正しくその情報の意味を理解する必要があります。そのため、次に実際にstageを例にPerformance Schemaの計測の仕組みを追いかけてみようと思います。

Performance Schemaの計測の仕組みを追う

まずはstageを例に実装を追う事で何を計測しているかを見ていきます。以下の内容を理解する上でMySQLのソースコードを手元に持ってきてデバッグモードでビルドしておくといいと思います。

MySQLのコードベースの解説はあまりしませんが、サーバーに関する部分だとざっくりとはストレージエンジンとそれ以外で分かれています。ストレージエンジンについては/storage以下に各ストレージエンジンの実装があり、例えばinnodbはstorage/innobase以下です。MySQLサーバーのストレージエンジン以外の部分、つまりparserやoptimizerやexecuterやその他もろもろは/sql以下に集まっています。

MySQLのような膨大なソースコードを目的無しに眺めるのは大変なのでまずは特徴的なキーワードでgrepしてみます。setup_instrumentsのNAMEカラムの値とか特徴的ですね。例えばalter tableに関連しそうな"preparing for alter table"で検索します。すると/sql/mysqld.ccになんかそれらしいものがあります。

PSI_stage_info stage_alter_inplace_prepare= { 0, "preparing for alter table", 0, PSI_DOCUMENT_ME};

今度は"stage_alter_inplace_prepare"で検索すると何やらsql_table.ccというファイルのinstant ddlの実装に関する場所で引っかかりました。ここはevents_stages_historyのSOURCEカラムの位置と同じ場所のようです。なので「THD_STAGE_INFO」というやつがPerformance Schemaに情報を保存する起点のようです。 該当箇所を含む関数"mysql_inplace_alter_table"の実装を眺めると他にもPSI_stage_infoの値が使われている事がわかります。

static bool mysql_inplace_alter_table(...){
…
  THD_STAGE_INFO(thd, stage_alter_inplace_prepare);
…
  THD_STAGE_INFO(thd, stage_alter_inplace);

…
  THD_STAGE_INFO(thd, stage_alter_inplace_commit);
…
  THD_STAGE_INFO(thd, stage_end);
...
}

おそらくTHD_STAGE_INFOの中で古いステージから新しいステージにステージが移るような処理をしていそうです。何をやってるかをさらに追うためにgdbでステップ実行しながら何が実行されるか見ていくと以下のような呼び出しが内部でされている事が分かりました。

├ THD::enter_stage
　└ set_proc_info(msg);
　　　└ include/mysql/psi/myaql_stage.h:inline_mysql_set_stage
　　　　└ storage/perfschema/pfs.cc:pfs_start_stage_v1

pfs_start_stage_v1にはtimer_valueという時間の計測をしていそうな変数があったりFinish old eventなどのコメントがあるので推測通り新しいステージの開始と古いステージの終了、それから時間の計測などが行われている事がわかりました。また、これはstorage/以下のファイルなのでperformance schema storage engineのレイヤーの役割として行われている事がわかりました。そういうわけでインターフェースとしてはとてもシンプルで、mysqld.ccで初期化して、該当する箇所でTHD_STAGE_INFOを呼べばなんかいい感じに計測してくれるようです。

waitについては種類によるかもしれませんが、rw_lockを取る場合だとlockの獲得からlockの解放までを計測しているようでした。例えばstorage/innobase/include/sync0rw.hのrw_lock_x_lockやrw_lock_x_unlockなどの関数の周辺でバックトレースを確認したりステップ実行をすると使われ方やPerformance Schemaへの登録などを追えると思います。例えばlock取得がPerformance Schemaに追加される様子は以下のような感じです。

├ storage/innobase/include/sync0rw.h:rw_lock_x_lock
　└ storage/innobase/include/sync0rw.ic:pfs_rw_lock_x_lock_func
　　　└ PSI_RWLOCK_CALL
　　　　└ storage/perfschema/pfs.cc:pfs_rw_lock_x_lock_func

rw_lockはさまざまな場所で取得されますが、rw_lock_x_lockなどはlocationを引数としてもらっていて、ここにファイル名や行番号が渡されているようです。

stageを自分で追加してみる

ここまでコードリーディングを通して仕組みを理解したので自分で新たにstageを追加してみます。差分は以下のリンクの通りで、本当に初期化してTHD_STAGE_INFOを追加するだけです。今回は変化が分かりやすいようにselectクエリなどで通るstage_optimizingをターゲットにして、その手前にstageを追加してsleepもさせました。

Comparing 8.0...add-stage-instrument-sample · shallow1729/mysql-server · GitHub

追加したinstrumentを有効にした上でクエリを実行してevents_stage_historyを確認すると以下のようになりました。

mysql> select EVENT_NAME, SOURCE, TIMER_WAIT from performance_schema.events_stages_history\G;
*************************** 1. row ***************************
EVENT_NAME: stage/sql/statistics
    SOURCE: sql_optimizer.cc:638
TIMER_WAIT: 103664000
*************************** 2. row ***************************
EVENT_NAME: stage/sql/preparing
    SOURCE: sql_optimizer.cc:722
TIMER_WAIT: 985088000
...
*************************** 8. row ***************************
EVENT_NAME: stage/sql/System lock
    SOURCE: lock.cc:331
TIMER_WAIT: 75016000
*************************** 9. row ***************************
EVENT_NAME: stage/sql/hogehogehogehoge
    SOURCE: sql_optimizer.cc:297
TIMER_WAIT: 5000366813000
*************************** 10. row ***************************
EVENT_NAME: stage/sql/optimizing
    SOURCE: sql_optimizer.cc:302
TIMER_WAIT: 45755000
10 rows in set (5.00 sec)

hogehogehogehogeという長い時間実行されている名前のstageが現れました。このように実装をいじる事で自分好みにカスタマイズもできそうです。

Performance Schemaをデータベースの改善に活用する

これでPerformance Schemaの仕組みはある程度追えるようになったので最後に軽くfreeeでPerformance Schemaの情報をきっかけにパラメーターの見直しを行った事例の紹介をします。

freeeはAWSのRDSを活用していて、冒頭で説明したPerformance Insightsという機能を活用しています。この機能の一つにスレッドのwaitの状態を定期的に取得して描画する機能があり、これはおそらくperformance_schema.events_waits_currentというその時刻のスレッドがどのwaitにいるかの情報を定期的に取得しているのだと思います。

ある日弊社のあるサービスの定期的なリリースの直後にCPU使用率が一時的に高くなる現象がありました。アクセス数が一時的に跳ね上がったというわけでもなかったのですが、Performance Insightsで該当時間のスレッドの状態を確認するとwait/synch/sxlock/innodb/btr_search_latchというwaitの状態のスレッドが多い事が分かりました。

Performane Insightsのダッシュボード。一定時間ごとにwaitの状態ごとのスレッド数がいくつかを取得して表示している
CPU使用率が一時的に上がった時のスレッドのwait状態を表すPerformance Insightsのダッシュボード。btr_searchまでで見切れているが、CPU使用率が上がっている時btr_search_latchの状態のスレッドが多いことを確認できた

同じ状態のスレッドが多いということはその状態の時間がかかっている可能性が高いのでbtr_search_latchについて調査すると、これはMySQLのAdaptive Hash Index(AHI)のハッシュテーブルの管理に使うlatchのようでした。なので、リリースでワークロードが変わった結果、一時的にハッシュテーブルの調整でlatchの競合が発生したと考えられました。対策策としてはinnodb_adaptive_hash_index_partsを調整して競合を減らすことや、AHIを無効にすることなどいくつかありますが、これをきっかけにデフォルトの設定値を見直す事ができました。

注意

ここまでPerformance Schemaの良いところをいろいろ解説しましたが、データ取得のためのオーバーヘッドの発生であったり、メモリなどのリソースの利用が追加で発生してしまうのでデメリットが無いわけではありません。これらの注意点を把握した上で活用してください。

最後に

今回はPerformance Schemaについて解説しました。内部実装と紐づけて分析する必要があるので簡単では無いですがうまく使えばパフォーマンスチューニングに繋げられるのかなと思いますし、そうでなくてもPerformance SchemaはMySQLのやっているお仕事の概観を教えてくれるので、これをきっかけにコードリーディングなんかをやると捗るのかなと思いました。

freee Developers Advent Calendar 2022は今日で最後です。最後までお付き合いくださいましてありがとうございました。良いお年を！