MySQLでトランザクションを追跡したい ~その1~
今日はエイプリルフールなのでどんな嘘をつこうかなと考えていたら午前中を過ぎていました。
この時期有名企業などもエイプリルフール企画を行っていたりしますが、嘘で分かるあからさまなものにしてほしいと思う今日このごろ。
本来であればLSM-Treeについて書こうと思ったのですが気が変わってまたMySQLの話です。
目標
遅いクエリはスロークエリログに出力されますが、遅いトランザクションはどうやって特定すればいいのだろうと考えていたらどうやら5.7からperformance_schema(以下p_sと記述)を使えばできるようなので試してみます。
なお今回はMySQL 8.0.19で試しました。
準備
まず簡単にp_sの仕組みについてですが、ソースコードのいたるところにinstrument(日本語に訳すと計器)と呼ばれるものが埋め込まれていて、そこを通ることでデータを取得します。instrumentからデータを収集するとオーバーヘッドがかかるため、収集対象のデータは必要最低限に押さえておくとよいでしょう。
デフォルトの設定では必要最低限の設定のみされていますが、適宜収集対象を変えることもできます。
各setupテーブルを有効にする
p_sにはsetupで始まるテーブルがいくつか存在します。
mysql80-root@localhost:p_s >show tables like 'setup%'; +------------------------+ | Tables_in_p_s (setup%) | +------------------------+ | setup_actors | | setup_consumers | | setup_instruments | | setup_objects | | setup_threads | +------------------------+ 5 rows in set (0.02 sec)
これらのテーブルはあるカテゴリーごとにそのデータを収集するかを設定します。 例えばsetup_actorsではユーザーやホストごとにデータを収集するかを設定できます。
今回使うのはsetup_consumers,setup_instrumentsです。
- setup_consumers
コンシューマーごとにデータを収集するかを設定します。コンシューマーとは収集したデータを一時的に保存しておく場所です。
mysql80-root@localhost:p_s >select * from setup_consumers; +----------------------------------+---------+ | NAME | ENABLED | +----------------------------------+---------+ | events_stages_current | NO | | events_stages_history | NO | | events_stages_history_long | NO | | events_statements_current | YES | | events_statements_history | YES | | events_statements_history_long | NO | | events_transactions_current | YES | | events_transactions_history | YES | | events_transactions_history_long | NO | | events_waits_current | NO | | events_waits_history | NO | | events_waits_history_long | NO | | global_instrumentation | YES | | thread_instrumentation | YES | | statements_digest | YES | +----------------------------------+---------+ 15 rows in set (0.02 sec)
ENABLEDがYESとなっているものが収集の対象となります。
今回の目標であるトランザクションの追跡をするために下記のクエリを実行します。
UPDATE setup_consumers SET ENABLED = 'YES' WHERE NAME LIKE '%transaction%';
- setup_instruments
instrumentごとにデータを収集するかを設定します。
mysql80-root@localhost:p_s >select * from setup_instruments where name like '%transaction%' and enabled = 'NO'; +-------------------------------------------------------+---------+-------+------------+------------+---------------+ | NAME | ENABLED | TIMED | PROPERTIES | VOLATILITY | DOCUMENTATION | +-------------------------------------------------------+---------+-------+------------+------------+---------------+ | wait/synch/mutex/sql/LOCK_transaction_cache | NO | NO | singleton | 0 | NULL | | stage/sql/Waiting for preceding transaction to commit | NO | NO | | 0 | NULL | | stage/sql/Waiting for dependent transaction to commit | NO | NO | | 0 | NULL | | stage/sql/Executing hook on transaction begin. | NO | NO | | 0 | NULL | +-------------------------------------------------------+---------+-------+------------+------------+---------------+ 4 rows in set (0.01 sec)
行数が多いため必要な箇所だけピックアップしています。 この内1行目は目標には不要そうなのでとりあえず除外して考えます。
下記クエリで必要なinstrumentを有効にします。
UPDATE setup_instruments SET ENABLED = 'YES', TIMED = 'YES' WHERE NAME LIKE 'stage/%transaction%' AND ENABLED = 'NO';
TIMEDをYESにするとタイマーから取得した値を用いて処理にかかった時間も測定できるようになります。
これで準備が整いました。
なお再起動してしまうとデフォルトの設定に戻ってしまうのでmy.cnfに記述する必要があります。
その他のテーブルについて詳しい内容を確認したい場合は公式リファレンスを参考してください。 MySQL :: MySQL 8.0 Reference Manual :: 26.12.2 Performance Schema Setup Tables
トランザクションの追跡
収集したデータは下記のテーブルから確認できそうです。
mysql80-root@localhost:p_s >show tables like '%transaction%'; +------------------------------------------------------+ | Tables_in_p_s (%transaction%) | +------------------------------------------------------+ | events_transactions_current | | events_transactions_history | | events_transactions_history_long | | events_transactions_summary_by_account_by_event_name | | events_transactions_summary_by_host_by_event_name | | events_transactions_summary_by_thread_by_event_name | | events_transactions_summary_by_user_by_event_name | | events_transactions_summary_global_by_event_name | +------------------------------------------------------+ 8 rows in set (0.02 sec)
summary_byを含むテーブルは各カテゴリーごとに集計した結果を表示します。例えばevents_transactions_summary_by_account_by_event_nameではアカウントごとの集計となります。
トランザクションを実行してみる
簡単なトランザクションを想定します。
BEGIN; SELECT a,b INTO @x, @y FROM t1 ORDER BY a LIMIT 1 LOCK IN SHARE MODE; INSERT INTO t2 VALUES (@x, @y); DELETE FROM t1 WHERE a = @x; COMMIT;
これをrootとは違うユーザで実行してみます。
実際に取得できた内容を確認してみます。
mysql80-root@localhost:p_s >select * from events_transactions_current where gtid <> 'AUTOMATIC'\G *************************** 1. row *************************** THREAD_ID: 49 EVENT_ID: 4 END_EVENT_ID: 8 EVENT_NAME: transaction STATE: COMMITTED TRX_ID: NULL GTID: 770710be-5cf4-11ea-b785-0800277e4b2d:8 XID_FORMAT_ID: NULL XID_GTRID: NULL XID_BQUAL: NULL XA_STATE: NULL SOURCE: transaction.cc:219 TIMER_START: 88235483705000 TIMER_END: 88584217354000 TIMER_WAIT: 348733649000 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: 3 NESTING_EVENT_TYPE: STATEMENT
とりあえず使えそうな情報はTHREAD_ID, EVENT_ID, STATE, GTID, TIMERあたりですかね。 GTIDが分かるので面倒ですがbinary_logからトランザクションの中身を確認することもできそうです。
TIMER_WAIT(TIMER_ENDとTIMER_STARTの差)でそのトランザクションにかかった時間が記録されるようです。
mysql80-root@localhost:p_s >select thread_id,sys.format_time(timer_wait) from events_transactions_current where gtid <> 'AUTOMATIC'; +-----------+-----------------------------+ | THREAD_ID | sys.format_time(timer_wait) | +-----------+-----------------------------+ | 49 | 348.73 ms | +-----------+-----------------------------+ 1 row in set (0.03 sec)
TIMERはどこからどこまでを計測しているのか
それではトランザクションの中にsleepを入れるとどうなるでしょうか。 上記のトランザクションに少し変更を加えてみます。
-- T1 BEGIN; SELECT SLEEP(1); SELECT a,b INTO @x, @y FROM t1 ORDER BY a LIMIT 1 LOCK IN SHARE MODE; INSERT INTO t2 VALUES (@x, @y); DELETE FROM t1 WHERE a = @x; COMMIT; -- T2 BEGIN; SELECT a,b INTO @x, @y FROM t1 ORDER BY a LIMIT 1 LOCK IN SHARE MODE; INSERT INTO t2 VALUES (@x, @y); DELETE FROM t1 WHERE a = @x; SELECT SLEEP(2); COMMIT;
T1実行後の結果
mysql80-root@localhost:p_s >select gtid,sys.format_time(timer_wait) from events_transactions_current where thread_id = 51; +-----------------------------------------+-----------------------------+ | GTID | sys.format_time(timer_wait) | +-----------------------------------------+-----------------------------+ | 770710be-5cf4-11ea-b785-0800277e4b2d:11 | 1.05 s | +-----------------------------------------+-----------------------------+ 1 row in set (0.01 sec)
T2実行後の結果
mysql80-root@localhost:p_s >select gtid,sys.format_time(timer_wait) from events_transactions_current where thread_id = 51; +-----------------------------------------+-----------------------------+ | GTID | sys.format_time(timer_wait) | +-----------------------------------------+-----------------------------+ | 770710be-5cf4-11ea-b785-0800277e4b2d:12 | 2.06 s | +-----------------------------------------+-----------------------------+ 1 row in set (0.01 sec)
このことからTIMER_WAITは単純にBEGIN~COMMITにかかった時間を計測している事がわかりました。
なお上記から分かるようにp_s.events_transactions_currentは最新のものしか反映されません。過去のものを参照したい場合はp_s.events_transactions_history(_long)を利用するとのことです。
ロールバックさせてみる
-- T3 BEGIN; SELECT a,b INTO @x, @y FROM t1 ORDER BY a LIMIT 1 LOCK IN SHARE MODE; INSERT INTO t2 VALUES (@x, @y); DELETE FROM t1 WHERE a = @x; SELECT SLEEP(3); ROLLBACK;
取得できたデータを見てみます。
mysql80-root@localhost:p_s >select * from events_transactions_current where thread_id = 51\G *************************** 1. row *************************** THREAD_ID: 51 EVENT_ID: 30 END_EVENT_ID: 35 EVENT_NAME: transaction STATE: ROLLED BACK TRX_ID: NULL GTID: AUTOMATIC XID_FORMAT_ID: NULL XID_GTRID: NULL XID_BQUAL: NULL XA_STATE: NULL SOURCE: transaction.cc:219 TIMER_START: 1371962257447000 TIMER_END: 1374997158206000 TIMER_WAIT: 3034900759000 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: 29 NESTING_EVENT_TYPE: STATEMENT 1 row in set (0.00 sec)
ちゃんとSTATE列がROLLED BACKとなっていますね。
つまりROLLED BACKされたトランザクションもしっかり追跡できそうです。
EVENT_IDとあるのでトランザクション内の各SQLはこのあたりから追跡できるのではないかと期待しています。 とりあえず今回はここまでにします。
