MySQLでトランザクションを追跡したい ~その4 まとめ編~
最近部屋の大掛かりな整理をしているのですが、とりあえずいらないコミックを売ろうと思い宅配買取サービスを利用したのですがいつになったら終わるんでしょう・・・
さて、今回はトランザクション追跡のまとめです。
過去3回にわたってperformance_schemaから過去に実行されたトランザクションを追跡することを考えてきました。
今回はトランザクション追跡に必要な各種設定や、実際にどのテーブルから欲しいデータを引っ張ってこれるのかをまとめます。
instrument,consumerの有効化
何はともあれperformance_schema(以降p_sと記述します)で調査を行うためには、予め該当するinstrumentとconsumerを有効にする必要があります。
※以降、単にtable名と表記した場合はすべてperformance_schema内のテーブルとします。またhoge()という表記はhoge関数であることを意味します。
例えば今回のトランザクションの追跡を行いたい場合は、次のようにinstumentを有効にしてあげます。
instrumentとはデータを収集する仕組みです。
使用するテーブルはsetup_instrumentsです。
UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME = 'transaction';
これでinstrumentの有効化ができます。 ENABLED列でinstrumentの有効化、TIMED列でタイマーの有効化ができます。
次はconsumerです。
instrumentがデータを収集する仕組みであることに対して、consumerはデータを保存しておく仕組み、すなわちテーブルです。
使用するテーブルはsetup_consumersです。
UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE '%transaction%';
このUPDATE文により影響を受けるテーブルは下記の3つです。(MySQL 8.0.19当時)
- events_transactions_current
現セッションの最後に実行されたトランザクションが記録される
- events_transactions_history
現セッションのトランザクションの内events_transactions_currentに記録されないものが記録される
- events_transactions_history_long
すでにセッションを閉じてしまったトランザクションが記録される
events_transactions_history, events_transactions_history_longについて、保管できる最大数というものが下記の変数によって設定されています。
- performance_schema_events_transactions_history_size
スレッドごとのevents_transactions_historyに保管される最大行数
- performance_schema_events_transactions_history_long_size
events_transactions_history_long_sizeの行数
これらの変数に-1(デフォルト値)を指定すると自動拡張されます。 また、これらの変数は動的には変更できないので、予めmy.cnfに記述しておく必要があります。 ただし、大きくするとその分メモリーを消費しますので注意してください。
余談ですが、現在performance_schemaによって消費されているメモリーの総量は下記コマンドで確認できます。
SHOW ENGINE performance_schema STATUS;
最後の行にperformance_schema.memoryと表示されますが、これが消費されているメモリーの総量です。
my.cnfによる設定の永続化
UPDATEによるinstrument, consumerの有効化は揮発性です。
すなわちMySQLを再起動するとデフォルトの設定に戻ってしまいます。
長期的に監視をしたい場合はmy.cnfに設定を記述しておくことをおすすめします。
[mysqld] performance-schema-instrument='transaction=ON' performance-schema-consumer-events-transactions-current=ON performance-schema-consumer-events-transactions-history=ON performance-schema-consumer-events-transactions-history-long=ON performance_schema_events_transactions_history_size=10 performance_schema_events_transactions_history_long_size=1000
無効化したい場合はONの部分をOFFとします。
なお、トランザクションを追跡するために大前提としてgtid_modeはONになっている必要があります。
トランザクションの追跡
さて、ここからが本題
実行例を例示して、トランザクションの追跡を行う場合の具体的なアクションを示していきます。
Case1 現在のセッションが実行した最新のトランザクションを追跡したい場合
events_transactions_currentからデータを引っ張ってこれます。
mysql80-root@localhost:p_s >select * from events_transactions_current where thread_id = 55\G *************************** 1. row *************************** THREAD_ID: 55 EVENT_ID: 91 END_EVENT_ID: 271 EVENT_NAME: transaction STATE: COMMITTED TRX_ID: NULL GTID: AUTOMATIC XID_FORMAT_ID: NULL XID_GTRID: NULL XID_BQUAL: NULL XA_STATE: NULL SOURCE: transaction.cc:219 TIMER_START: 240621991211283000 TIMER_END: 240622000148798000 TIMER_WAIT: 8937515000 ACCESS_MODE: READ WRITE ISOLATION_LEVEL: REPEATABLE READ AUTOCOMMIT: NO NUMBER_OF_SAVEPOINTS: 0 NUMBER_OF_ROLLBACK_TO_SAVEPOINT: 0 NUMBER_OF_RELEASE_SAVEPOINT: 0 OBJECT_INSTANCE_BEGIN: NULL NESTING_EVENT_ID: 83 NESTING_EVENT_TYPE: STATEMENT 1 row in set (0.00 sec)
そのセッションが生きている場合、sys.ps_thread_id()からthread_idが分かります。
このテーブルだけで分かる情報は限られてきますが、トランザクション全体の実行時間はTIMER_WAIT列から分かります。sys.format_time()などを使って分かりやすい値に整形してあげると良いでしょう。
mysql80-root@localhost:p_s >select event_id,sys.format_time(timer_wait) from events_transactions_current where thread_id = 55; +----------+-----------------------------+ | EVENT_ID | sys.format_time(timer_wait) | +----------+-----------------------------+ | 91 | 8.94 ms | +----------+-----------------------------+ 1 row in set (0.02 sec)
なお、sys.ps_thread_trx_info()を使うとトランザクションの詳細を調べることができます。
引数には対象のthread_idを渡してあげます。
mysql80-root@localhost:sys >select sys.ps_thread_trx_info(59)\G *************************** 1. row *************************** sys.ps_thread_trx_info(59): [ { "time": "24.71 ms", "state": "COMMITTED", "mode": "READ WRITE", "autocommitted": "NO", "gtid": "AUTOMATIC", "isolation": "REPEATABLE READ", "statements_executed": [ { "sql_text": "SELECT sys.ps_thread_id(NULL)", "time": "3.75 ms", "schema": "koreshiki", "rows_examined": 1, "rows_affected": 0, "rows_sent": 1, "tmp_tables": 0, "tmp_disk_tables": 0, "sort_rows": 0, "sort_merge_passes": 0 }, { "sql_text": "SELECT a, b FROM t1 ORDER BY a LIMIT 2 FOR UPDATE", "time": "2.50 ms", "schema": "koreshiki", "rows_examined": 2, "rows_affected": 0, "rows_sent": 2, "tmp_tables": 0, "tmp_disk_tables": 0, "sort_rows": 0, "sort_merge_passes": 0 }, { "sql_text": "COMMIT", "time": "490.82 us", "schema": "koreshiki", "rows_examined": 0, "rows_affected": 0, "rows_sent": 0, "tmp_tables": 0, "tmp_disk_tables": 0, "sort_rows": 0, "sort_merge_passes": 0 } ] } ] 1 row in set (0.02 sec)
現在のセッションの最新のトランザクションしか確認できませんが、ステートメントごとの実行時間など非常に詳しい内容が分かります。
再現性のあるトランザクションの場合には十分使える方法なのではないでしょうか。
Case2 現在のセッションが実行した過去のトランザクションを追跡したい場合
events_transactions_historyからデータを引っ張ってこれます。
mysql80-root@localhost:p_s >select * from events_transactions_history where thread_id = 59\G *************************** 1. row *************************** THREAD_ID: 59 EVENT_ID: 91 END_EVENT_ID: 286 EVENT_NAME: transaction STATE: COMMITTED TRX_ID: NULL GTID: AUTOMATIC XID_FORMAT_ID: NULL XID_GTRID: NULL XID_BQUAL: NULL XA_STATE: NULL SOURCE: transaction.cc:219 TIMER_START: 243646465000736000 TIMER_END: 243646489708277000 TIMER_WAIT: 24707541000 ACCESS_MODE: READ WRITE ISOLATION_LEVEL: REPEATABLE READ AUTOCOMMIT: NO NUMBER_OF_SAVEPOINTS: 0 NUMBER_OF_ROLLBACK_TO_SAVEPOINT: 0 NUMBER_OF_RELEASE_SAVEPOINT: 0 OBJECT_INSTANCE_BEGIN: NULL NESTING_EVENT_ID: 83 NESTING_EVENT_TYPE: STATEMENT 1 row in set (0.00 sec)
上述したとおりevents_transactions_historyには特定のスレッドに対してperformance_schema_events_transactions_history_size行しか保存されないので注意してください。
mysql80-root@localhost:p_s >show variables like 'performance_schema_events_transactions_history_size'; +-----------------------------------------------------+-------+ | Variable_name | Value | +-----------------------------------------------------+-------+ | performance_schema_events_transactions_history_size | 10 | +-----------------------------------------------------+-------+ 1 row in set (0.01 sec) -- 現在のevents_transactions_historyに保管されているthread_id = 60となるデータ件数の確認 mysql80-root@localhost:p_s >select thread_id, event_id from events_transactions_history where thread_id = 60 order by event_id; +-----------+----------+ | THREAD_ID | EVENT_ID | +-----------+----------+ | 60 | 432 | | 60 | 498 | | 60 | 564 | | 60 | 630 | | 60 | 696 | | 60 | 762 | | 60 | 828 | | 60 | 894 | | 60 | 960 | | 60 | 1052 | +-----------+----------+ 10 rows in set (0.01 sec) -- 別セッション(thread_id = 60)でトランザクションを実行 mysql80-koreshiki@localhost:koreshiki >begin; select @x + 1 into @x; commit; Query OK, 0 rows affected (0.00 sec) Query OK, 1 row affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) -- 一番古いデータ(event_id = 432)が削除され新しいデータ(event_id = 1118)が挿入された mysql80-root@localhost:p_s >select thread_id, event_id from events_transactions_history where thread_id = 60 order by event_id; +-----------+----------+ | THREAD_ID | EVENT_ID | +-----------+----------+ | 60 | 498 | | 60 | 564 | | 60 | 630 | | 60 | 696 | | 60 | 762 | | 60 | 828 | | 60 | 894 | | 60 | 960 | | 60 | 1052 | | 60 | 1118 | +-----------+----------+ 10 rows in set (0.01 sec)
Case3 セッションがすでに閉じられた過去のトランザクションを追跡したい場合
events_transactions_history_longからデータを引っ張ってこれます。
ただし大抵の場合はthread_idが分からないことがほとんどだと思うので、EVENT_NAME='TRANSACTION' AND NESTING_EVENT_TYPE='STATEMENT'などの条件で絞ったほうが良さそうです。
そもそもevents_transactions_history_longを調査したい時というのは、トランザクションが遅くなった、トランザクション中にロック待ちが多発しているといった原因を調べたいときがほとんどだと思います。
これを踏まえると、例えば遅いトランザクションを特定したいといった場合は次のクエリが使えます。
mysql80-root@localhost:p_s >select thread_id,event_id,nesting_event_id,sys.format_time(timer_wait) from events_transactions_history_long where event_name = 'transaction' and nesting_event_type = 'statement' order by timer_wait desc limit 5; +-----------+----------+------------------+-----------------------------+ | THREAD_ID | EVENT_ID | NESTING_EVENT_ID | sys.format_time(timer_wait) | +-----------+----------+------------------+-----------------------------+ | 53 | 93 | 85 | 8.04 s | | 50 | 198 | 190 | 6.54 s | | 51 | 200 | 192 | 6.53 s | | 56 | 41487 | 41387 | 492.26 ms | | 56 | 40612 | 40512 | 362.38 ms | +-----------+----------+------------------+-----------------------------+ 5 rows in set (0.04 sec)
events_transactions_history_longから欲しいデータを引っ張ってくるにはある程度予測を立てて探すことが必要になりそうです。
こちらのテーブルも同様にperformance_schema_events_transactions_history_long_size行数しかデータを保管できないので注意してください。
トランザクションの調査
上述した方法でトランザクションの特定、具体的にはthread_idや各event_idが分かれば各SQL文でどの程度時間がかかったのか、どのあたりでロック待ちが出ているのかなど、より詳細な内容を確認することができます。
予め次の操作が必要です。（デフォルトでONになっているケースが多いです）
UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME LIKE 'statement/%'; UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE 'events_statments%';
- events_statements_current
そのthread_id(セッションが生きている)が最後に実行したステートメントを記録する
- events_statements_history
performance_schema_events_statements_hisotry_size行のみthread_idごとに実行されたステートメントを記録する
- events_statements_history_long
performance_schema_events_statements_hisotry_long_size行のみ実行されたステートメントを記録する
基本的にevents_statements_history, events_statements_history_longから調査するケースが多いと思います。
セッションが生きている場合
この場合thread_idが分かるので、そこから調査を進めていきます。
mysql80-root@localhost:p_s >select thread_id,event_id,end_event_id,nesting_event_id,sys.format_time(timer_wait) from events_transactions_history where thread_id = 62; +-----------+----------+--------------+------------------+-----------------------------+ | THREAD_ID | EVENT_ID | END_EVENT_ID | NESTING_EVENT_ID | sys.format_time(timer_wait) | +-----------+----------+--------------+------------------+-----------------------------+ | 62 | 91 | 286 | 83 | 25.25 ms | | 62 | 306 | 482 | 298 | 23.92 ms | +-----------+----------+--------------+------------------+-----------------------------+ 2 rows in set (0.01 sec)
この内1行目のトランザクションについて調査したいと思います。
events_transactions_historyからのevent_id(= 91)をevents_statements_historyのnesting_event_idとして欲しいデータを取得します。
つまり次のクエリで取得できます。
select * from events_statements_history where nesting_event_id = (select event_id from events_transactions_history where thread_id = 62 order by event_id limit 1);
必要なデータだけを取得して、下記の結果を得られました。
+-----------+----------+--------------+---------------------------------------------------+-----------------------------+ | THREAD_ID | EVENT_ID | END_EVENT_ID | SQL_TEXT | sys.format_time(timer_wait) | +-----------+----------+--------------+---------------------------------------------------+-----------------------------+ | 62 | 103 | 139 | SELECT sys.ps_thread_id(NULL) | 4.49 ms | | 62 | 144 | 264 | SELECT a, b FROM t1 ORDER BY a LIMIT 2 FOR UPDATE | 2.13 ms | | 62 | 269 | 293 | COMMIT | 332.84 us | +-----------+----------+--------------+---------------------------------------------------+-----------------------------+ 3 rows in set (0.01 sec)
セッションがすでに閉じられている場合
対象となるテーブルが変わるだけで探し方は対して変わりません。
上述したとおりthread_idやevent_idはevents_transactions_history_longからあたりをつけて探します。
今回はCase3で見たevent_id = 93となるトランザクションを追います。
mysql80-root@localhost:p_s >select thread_id,event_id,end_event_id,sql_text,sys.format_time(timer_wait) timer_wait, sys.format_time(lock_time) lock_time from events_statements_history_long where nesting_event_id = 93; +-----------+----------+--------------+---------------------------------------------------+------------+-----------+ | THREAD_ID | EVENT_ID | END_EVENT_ID | SQL_TEXT | timer_wait | lock_time | +-----------+----------+--------------+---------------------------------------------------+------------+-----------+ | 53 | 105 | 388 | SELECT sys.ps_thread_id(NULL) | 9.53 ms | 4.67 ms | | 53 | 393 | 659 | SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE | 8.00 s | 7.99 s | | 53 | 664 | 690 | COMMIT | 509.89 us | 0 ps | +-----------+----------+--------------+---------------------------------------------------+------------+-----------+ 3 rows in set (0.05 sec)
timer_waitからそのステートメントの実行にかかった時間が、lock_timeからそのステートメントを実行にするのにかかったロック待ちの時間が分かります。
この結果からステートメント実行自体に時間がかかったわけではなく、ロック待ちで時間がかかっていることが分かります。
1点注意として、どうやらsql_text列が同じすなわちdigest列が同じだとnesting_event_idも同じになるよう(?)です。
ただしこの場合は逆に、timer_waitは変わってくるはずなので、ここから全てのスレッドで同様にパフォーマンスが悪いのか、それとも特定のスレッドだけパフォーマンスが悪いのかといった調査が可能です。
mysql80-root@localhost:p_s >select thread_id,event_id,sql_text,sys.format_time(timer_wait) from events_statements_history_long where nesting_event_id = 91; +-----------+----------+---------------------------------------------------+-----------------------------+ | THREAD_ID | EVENT_ID | SQL_TEXT | sys.format_time(timer_wait) | +-----------+----------+---------------------------------------------------+-----------------------------+ | 55 | 103 | SELECT sys.ps_thread_id(NULL) | 1.26 ms | | 55 | 144 | SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE | 868.52 us | | 55 | 254 | COMMIT | 257.34 us | | 58 | 103 | SELECT sys.ps_thread_id(NULL) | 4.97 ms | | 58 | 144 | SELECT a, b FROM t1 ORDER BY a LIMIT 2 FOR UPDATE | 8.61 ms | | 58 | 269 | COMMIT | 263.79 us | | 59 | 103 | SELECT sys.ps_thread_id(NULL) | 3.75 ms | | 59 | 144 | SELECT a, b FROM t1 ORDER BY a LIMIT 2 FOR UPDATE | 2.50 ms | | 59 | 269 | COMMIT | 490.82 us | | 61 | 103 | SELECT sys.ps_thread_id(NULL) | 4.96 ms | | 61 | 144 | SELECT a, b FROM t1 ORDER BY a LIMIT 2 FOR UPDATE | 3.33 ms | | 61 | 269 | COMMIT | 282.59 us | | 62 | 103 | SELECT sys.ps_thread_id(NULL) | 4.49 ms | | 62 | 144 | SELECT a, b FROM t1 ORDER BY a LIMIT 2 FOR UPDATE | 2.13 ms | | 62 | 269 | COMMIT | 332.84 us | | 63 | 103 | SELECT sys.ps_thread_id(NULL) | 2.96 ms | | 63 | 144 | SELECT a, b FROM t1 ORDER BY a LIMIT 2 FOR UPDATE | 11.87 s | | 63 | 290 | COMMIT | 508.29 us | +-----------+----------+---------------------------------------------------+-----------------------------+ 18 rows in set (0.04 sec)
さらなる調査をしたい場合
今回は割愛しますが、さらにこのロック待ちがどのようなロック(DMLによるロックなのか、DDLによるロックなのかなど)を調べるにはevents_stages_history_longを使用します。
先ほどと同じようにevents_statements_history_longから取得したevent_id(= 393)をevents_stages_history_longのnesting_event_idとして探すことができます。
ただしevents_statements_history_longも今まで見てきた_longテーブルと同様にperformance_schema_events_stages_history_long_sizeが保管できる行数の上限になることには注意が必要です。この値を有限にしておくとあまりにも過去のデータは取得できません。（その場合は-1を設定して自動拡張機能を有効にしておく必要があります）
できなかったこと
下記のことは確認できませんでした。（少なくとも僕が調べた限り方法がなさそうでした）
- thread_idからユーザーを特定すること
例えばevents_statements_history_longからthread_idを特定できたとしましょう。
しかしthreadsテーブルやsys.processlistなどでは現在のthread_idからしかユーザーを特定することができませんので、過去のトランザクションを実行したユーザーが誰だったかまでは調査できません。
アプリケーションユーザーを固定にしても、そのトランザクションを実行するホストが複数ある場合には、特定のホストだけパフォーマンスが悪いのか、アプリケーションサーバ全体のパフォーマンスが悪いのかはMySQLだけでは調査が困難でしょう。
この場合はアプリケーションサーバ側でしっかりログを取り、異常を検知できる仕組みを備えておく必要があります。
- トランザクションが実行された時刻
events_transactions_currentなどのTIMER_START列、TIMER_END列はそれぞれイベントの開始時間および終了時間らしいのですが、そこから時刻を確かめることはできませんでした。
というのも次のように単純なtimestampとは桁数が違いすぎるのです。
mysql80-root@localhost:p_s >select timer_start from events_transactions_current order by thread_id desc limit 1; +--------------------+ | TIMER_START | +--------------------+ | 254795343099128000 | +--------------------+ 1 row in set (0.00 sec) mysql80-root@localhost:p_s >select @@timestamp; +-------------------+ | @@timestamp | +-------------------+ | 1586765505.007534 | +-------------------+ 1 row in set (0.00 sec)
TIMER_END から TIMER_STARTを引いた値が実行時間すなわちTIMER_WAITになるのはいいのですが、そのトランザクション自体がいつ実行されたのかはわ分かりません。
このあたりはソースコードを確認してみる必要がありそうです・・・
まとめ
- トランザクションの追跡は
p_s.events_transactions%テーブルから確認できる - 現セッションの最新トランザクションは
_current, 現セッションの過去トランザクションは_history,過去セッションのトランザクションは_history_longテーブルからそれぞれ取得できる _currentテーブル以外は変数で保管できる最大数を制御できる(消費メモリー量とのトレードオフ)events_transactions%テーブルのTIMER_WAIT列からトランザクションにかかった時間が分かる(sys.format_time()関数が便利)events_transactions%テーブルのEVENT_ID列をp_s.events_statements%テーブルのNESTING_EVENT_ID列として各ステートメントを調べることができる- できないことなどもあるのでperformance_schemaを過信せずアプリケーション側でもログの取得はしておく必要がある
参考にさせていただいたサイト
今回は主にMySQLの公式リファレンスを参考させていただきました。
MySQL :: MySQL 8.0 Reference Manual :: 26.12.6.1 The events_statements_current Table
MySQL :: MySQL 8.0 Reference Manual :: 12.6 Date and Time Functions
