MySQLでトランザクションを追跡したい ~その2~
在宅勤務が続き運動不足を感じたので、筋トレを始めました。
普段使わない筋肉を酷使するので翌日筋肉痛がつらい・・・ですが、以前より人間らしい生活をしている気がします。
前回の記事はこちら
koreshiki-nanno.hatenablog.com
前回、performance_schema(以下p_s)内のevents_transactions_currentもしくはevents_transactions_history(_long)からトランザクションを追跡できることがわかりました。
今回はもう少し踏み込んでそのトランザクションがどのようなクエリを実行したのか、ロールバックしていたら直前のクエリは何だったか、また可能であれば各クエリにはどの程度時間を要したかといったことを調査できるか試してみます！
前回使用したトランザクションを今回も利用します。
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;
実行します。
mysql80-koreshiki@localhost:koreshiki >select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 15 | +-----------------+ 1 row in set (0.00 sec) mysql80-koreshiki@localhost:koreshiki >BEGIN; Query OK, 0 rows affected (0.00 sec) mysql80-koreshiki@localhost:koreshiki >SELECT a,b INTO @x, @y FROM t1 ORDER BY a LIMIT 1 LOCK IN SHARE MODE; Query OK, 1 row affected (0.01 sec) mysql80-koreshiki@localhost:koreshiki >INSERT INTO t2 VALUES (@x, @y); Query OK, 1 row affected (0.01 sec) mysql80-koreshiki@localhost:koreshiki >DELETE FROM t1 WHERE a = @x; Query OK, 1 row affected (0.00 sec) mysql80-koreshiki@localhost:koreshiki >COMMIT; Query OK, 0 rows affected (0.02 sec)
まずはトランザクションの内容を確認します。
mysql80-root@localhost:p_s >select * from events_transactions_current where thread_id = (select thread_id from threads where processlist_id = 15)\G *************************** 1. row *************************** THREAD_ID: 54 EVENT_ID: 157 END_EVENT_ID: 968 EVENT_NAME: transaction STATE: COMMITTED TRX_ID: NULL GTID: 770710be-5cf4-11ea-b785-0800277e4b2d:16 XID_FORMAT_ID: NULL XID_GTRID: NULL XID_BQUAL: NULL XA_STATE: NULL SOURCE: transaction.cc:219 TIMER_START: 235440978172163000 TIMER_END: 235441015077746000 TIMER_WAIT: 36905583000 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: 149 NESTING_EVENT_TYPE: STATEMENT 1 row in set (0.01 sec)
このトランザクションで実行されたクエリはp_s.events_statements_historyで確認できそうです。p_s.events_statements_currentは最後に実行されたクエリしか記録されないので、今回は使えません。上記クエリでevent_id = 157が取得できたので早速確認してみます。
mysql80-root@localhost:p_s >select * from events_statements_history where event_id = 157; Empty set (0.00 sec)
おや？Emptyですね。
とりあえずthread_id = 54で探してみます。
mysql80-root@localhost:p_s >select * from events_statements_history where thread_id = 54\G : 省略 : *************************** 9. row *************************** THREAD_ID: 54 EVENT_ID: 807 END_EVENT_ID: 975 EVENT_NAME: statement/sql/commit SOURCE: init_net_server_extension.cc:95 TIMER_START: 235441003147387000 TIMER_END: 235441015263892000 TIMER_WAIT: 12116505000 LOCK_TIME: 0 SQL_TEXT: COMMIT DIGEST: f2b9be5f0f32ca7507e4ddf133cd2fad0993a1c26fde9caa6f067b1af2b7603c DIGEST_TEXT: COMMIT CURRENT_SCHEMA: koreshiki OBJECT_TYPE: NULL OBJECT_SCHEMA: NULL OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: NULL MYSQL_ERRNO: 0 RETURNED_SQLSTATE: 00000 MESSAGE_TEXT: NULL ERRORS: 0 WARNINGS: 0 ROWS_AFFECTED: 0 ROWS_SENT: 0 ROWS_EXAMINED: 0 CREATED_TMP_DISK_TABLES: 0 CREATED_TMP_TABLES: 0 SELECT_FULL_JOIN: 0 SELECT_FULL_RANGE_JOIN: 0 SELECT_RANGE: 0 SELECT_RANGE_CHECK: 0 SELECT_SCAN: 0 SORT_MERGE_PASSES: 0 SORT_RANGE: 0 SORT_ROWS: 0 SORT_SCAN: 0 NO_INDEX_USED: 0 NO_GOOD_INDEX_USED: 0 NESTING_EVENT_ID: 157 NESTING_EVENT_TYPE: TRANSACTION NESTING_EVENT_LEVEL: 0 STATEMENT_ID: 99 9 rows in set (0.01 sec)
どうやらNESTING_EVENT_ID、NESTING_EVENT_TYPEあたりが使えそうですね。
mysql80-root@localhost:p_s >SELECT
-> thread_id,
-> event_id,
-> end_event_id,
-> sys.format_time(timer_wait),
-> sql_text
-> nesting_event_id,
-> nesting_event_type,
-> nesting_event_level
-> FROM
-> events_statements_history
-> WHERE
-> nesting_event_id = 157;
+-----------+----------+--------------+-----------------------------+----------------------------------------------------------------------+--------------------+---------------------+
| THREAD_ID | EVENT_ID | END_EVENT_ID | sys.format_time(timer_wait) | nesting_event_id | NESTING_EVENT_TYPE | NESTING_EVENT_LEVEL |
+-----------+----------+--------------+-----------------------------+----------------------------------------------------------------------+--------------------+---------------------+
| 54 | 169 | 268 | 2.46 ms | SELECT a,b INTO @x, @y FROM t1 ORDER BY a LIMIT 1 LOCK IN SHARE MODE | TRANSACTION | 0 |
| 54 | 273 | 485 | 3.15 ms | INSERT INTO t2 VALUES (@x, @y) | TRANSACTION | 0 |
| 54 | 490 | 802 | 3.51 ms | DELETE FROM t1 WHERE a = @x | TRANSACTION | 0 |
| 54 | 807 | 975 | 12.12 ms | COMMIT | TRANSACTION | 0 |
+-----------+----------+--------------+-----------------------------+----------------------------------------------------------------------+--------------------+---------------------+
4 rows in set (0.02 sec)
なんとかトランザクション内で実行されたクエリを表示できました。 今度はロールバックするようなトランザクションを実行します。上記トランザクションでCOMMITではなくROLL BACKするようにします。
mysql80-root@localhost:p_s >SELECT
-> thread_id,
-> event_id,
-> end_event_id,
-> sys.format_time(timer_wait),
-> sql_text
-> nesting_event_id,
-> nesting_event_type,
-> nesting_event_level
-> FROM
-> events_statements_history
-> WHERE
-> nesting_event_id = (
-> SELECT
-> event_id
-> FROM
-> events_transactions_current
-> WHERE
-> thread_id = 54
-> )
-> ;
+-----------+----------+--------------+-----------------------------+----------------------------------------------------------------------+--------------------+---------------------+
| THREAD_ID | EVENT_ID | END_EVENT_ID | sys.format_time(timer_wait) | nesting_event_id | NESTING_EVENT_TYPE | NESTING_EVENT_LEVEL |
+-----------+----------+--------------+-----------------------------+----------------------------------------------------------------------+--------------------+---------------------+
| 54 | 1000 | 1084 | 1.39 ms | SELECT a,b INTO @x, @y FROM t1 ORDER BY a LIMIT 1 LOCK IN SHARE MODE | TRANSACTION | 0 |
| 54 | 1089 | 1288 | 1.86 ms | INSERT INTO t2 VALUES (@x, @y) | TRANSACTION | 0 |
| 54 | 1293 | 1456 | 2.42 ms | DELETE FROM t1 WHERE a = @x | TRANSACTION | 0 |
| 54 | 1461 | 1812 | 11.48 ms | ROLLBACK | TRANSACTION | 0 |
+-----------+----------+--------------+-----------------------------+----------------------------------------------------------------------+--------------------+---------------------+
いいですね！
とりあえず現在もコネクションがあるスレッドに関してはトランザクションの追跡ができそうなことがわかりました。
次回はすでにコネクションが切れてしまっている過去のトランザクションについても追跡が可能か確認してみようと思います。
