MySQLでトランザクションを追跡したい ~その3~
絶賛部屋の整理中なのですが、書籍が思ったより多くて苦戦しています。
大学時代に足繁く紀伊国屋に寄ってよく本を買っていったのですが、よくもまあここまで買ったなと我ながら思います。
さて、トランザクション追跡第3段です。
前回の記事はこちら
koreshiki-nanno.hatenablog.com
前回は過去に実行されたトランザクション内で使われた各クエリを確認できることがわかりました。
運用・保守などをしていると大抵の場合、現在のトランザクションを調べることより過去に実行されたトランザクションを実行したいといったことが多いのではないでしょうか。
今回はコネクションプーリングなどを使っていない環境で、過去に実行されたトランザクションについて調べることを考えます。
この場合そのスレッドはすでに存在していませんから、今までのようにp_s.events_transaction_currentは利用できません。
検証
今回は次のトランザクションを追ってみます。
-- T1 BEGIN; SELECT sys.ps_thread_id(NULL); SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE; COMMIT;
何の意味も無いトランザクションですが、検証用ということで
thread_idが分かる場合
念のためthread_idで追跡できるようにsys.ps_thread_idを呼んでいます。引数にNULLもしくは自身のprocesslist_idを渡すことでthread_idを取得できます。
mysql80-koreshiki@localhost:koreshiki >BEGIN; Query OK, 0 rows affected (0.00 sec) mysql80-koreshiki@localhost:koreshiki >SELECT sys.ps_thread_id(NULL); +------------------------+ | sys.ps_thread_id(NULL) | +------------------------+ | 56 | +------------------------+ 1 row in set, 1 warning (0.00 sec) mysql80-koreshiki@localhost:koreshiki >SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE; +---+------+ | a | b | +---+------+ | 9 | bbb | +---+------+ 1 row in set (0.01 sec) mysql80-koreshiki@localhost:koreshiki >COMMIT; Query OK, 0 rows affected (0.01 sec) mysql80-koreshiki@localhost:koreshiki >EXIT Bye
さてこのトランザクションを追ってみましょう。
mysql80-root@localhost:p_s >select * from events_transactions_current where thread_id = 56; Empty set (0.02 sec) mysql80-root@localhost:p_s >select * from events_transactions_history where thread_id = 56; Empty set (0.00 sec)
events_transactions_currentに存在しないのは分かるのですが、events_transactions_historyにも存在しませんね。ということはevents_transactions_history_longに存在するのでしょうか。
mysql80-root@localhost:p_s >select * from events_transactions_history_long where thread_id = 56\G *************************** 1. row *************************** THREAD_ID: 56 EVENT_ID: 91 END_EVENT_ID: 274 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: 244046521866884000 TIMER_END: 244046549548627000 TIMER_WAIT: 27681743000 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.01 sec)
予想通りevents_transactions_history_longに存在しました。
前回のようにNESTING_EVENT_IDを使ってp_s.events_statements_history, p_s.events_statements_history_longあたりを調べてみます。
mysql80-root@localhost:p_s >select * from events_statements_history where nesting_event_id = 91; Empty set (0.00 sec)
events_statements_historyには存在しないのでevents_statements_history_longにあるようです。
mysql80-root@localhost:p_s >select thread_id, event_id, end_event_id, event_name, sys.format_time(timer_wait), sys.format_time(lock_time), sql_text, rows_affected, rows_sent, rows_examined, nesting_event_id, nesting_event_type, nesting_event_level, statement_id from events_statements_history_long where nesting_event_id = 91; +-----------+----------+--------------+----------------------+-----------------------------+----------------------------+---------------------------------------------------+---------------+-----------+---------------+------------------+--------------------+---------------------+--------------+ | THREAD_ID | EVENT_ID | END_EVENT_ID | EVENT_NAME | sys.format_time(timer_wait) | sys.format_time(lock_time) | SQL_TEXT | ROWS_AFFECTED | ROWS_SENT | ROWS_EXAMINED | NESTING_EVENT_ID | NESTING_EVENT_TYPE | NESTING_EVENT_LEVEL | STATEMENT_ID | +-----------+----------+--------------+----------------------+-----------------------------+----------------------------+---------------------------------------------------+---------------+-----------+---------------+------------------+--------------------+---------------------+--------------+ | 56 | 103 | 142 | statement/sql/select | 4.85 ms | 3.36 ms | SELECT sys.ps_thread_id(NULL) | 0 | 1 | 1 | 91 | TRANSACTION | 0 | 60 | | 56 | 147 | 252 | statement/sql/select | 2.53 ms | 1.56 ms | SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE | 0 | 1 | 1 | 91 | TRANSACTION | 0 | 63 | | 56 | 257 | 282 | statement/sql/commit | 511.14 us | 0 ps | COMMIT | 0 | 0 | 0 | 91 | TRANSACTION | 0 | 64 | +-----------+----------+--------------+----------------------+-----------------------------+----------------------------+---------------------------------------------------+---------------+-----------+---------------+------------------+--------------------+---------------------+--------------+
とりあえず欲しいデータは取れそうです。
thread_idがわからない場合
ただしこれは予めthread_idを知っていたためできた方法でした。
今度はthread_idを知らない体でやってみます。 トランザクションが遅くなったことを実現したいので、少し強引ですが予め対象のテーブルにロックを掛けます。
-- 対象のテーブルにロックをかける mysql80-root@localhost:koreshiki >lock tables t1 write; Query OK, 0 rows affected (0.03 sec) -- 別セッションがトランザクションを開始 mysql80-koreshiki@localhost:koreshiki >BEGIN; Query OK, 0 rows affected (0.00 sec) mysql80-koreshiki@localhost:koreshiki >SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE; +---+------+ | a | b | +---+------+ | 9 | bbb | +---+------+ 1 row in set (8.00 sec) -- 上記トランザクションでロック待ちが生じていることを確認 mysql80-root@localhost:koreshiki >show processlist; +----+-----------------+-----------+-----------+---------+------+---------------------------------+---------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-----------------+-----------+-----------+---------+------+---------------------------------+---------------------------------------------------+ | 4 | event_scheduler | localhost | NULL | Daemon | 727 | Waiting on empty queue | NULL | | 8 | root | localhost | p_s | Sleep | 190 | | NULL | | 9 | root | localhost | p_s | Sleep | 708 | | NULL | | 13 | root | localhost | koreshiki | Query | 0 | starting | show processlist | | 14 | koreshiki | localhost | koreshiki | Query | 4 | Waiting for table metadata lock | SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE | +----+-----------------+-----------+-----------+---------+------+---------------------------------+---------------------------------------------------+ 5 rows in set (0.00 sec) -- ロックを解除 mysql80-root@localhost:koreshiki >unlock tables; Query OK, 0 rows affected (0.00 sec) -- COMMITしてセッションを閉じる mysql80-koreshiki@localhost:koreshiki >COMMIT; Query OK, 0 rows affected (0.00 sec) mysql80-koreshiki@localhost:koreshiki >EXIT Bye
遅いトランザクションを特定したいので、timer_waitでソートして上位何件かを確認してみます。
mysql80-root@localhost:p_s >select thread_id, event_id, end_event_id, state, nesting_event_id, nesting_event_type, sys.format_time(timer_wait) from events_traansactions_history_long order by timer_wait desc limit 5; +-----------+----------+--------------+-----------+------------------+--------------------+-----------------------------+ | THREAD_ID | EVENT_ID | END_EVENT_ID | STATE | NESTING_EVENT_ID | NESTING_EVENT_TYPE | sys.format_time(timer_wait) | +-----------+----------+--------------+-----------+------------------+--------------------+-----------------------------+ | 53 | 93 | 681 | COMMITTED | 85 | STATEMENT | 8.04 s | | 50 | 198 | 2170 | COMMITTED | 190 | STATEMENT | 6.54 s | | 51 | 200 | 1544 | COMMITTED | 192 | STATEMENT | 6.53 s | | 2 | 211296 | 246193 | COMMITTED | NULL | NULL | 88.69 ms | | 47 | 28908 | 30364 | COMMITTED | 27463 | STATEMENT | 15.86 ms | +-----------+----------+--------------+-----------+------------------+--------------------+-----------------------------+ 5 rows in set (0.01 sec)
上1件についてthread_id, event_id, nesting_event_idあたりを頼りにp_s.events_statements_history(_long)を調査します。
（thread_id = 50, 51のものに関しては過去検証によるものなのでスルー）
mysql80-root@localhost:p_s >select event_id, end_event_id, event_name, sql_text, nesting_event_type, sys.format_time(timer_wait),sys.format_time(lock_time) fmrom events_statements_history_long where nesting_event_id = 93; +----------+--------------+----------------------+---------------------------------------------------+--------------------+-----------------------------+----------------------------+ | EVENT_ID | END_EVENT_ID | EVENT_NAME | SQL_TEXT | NESTING_EVENT_TYPE | sys.format_time(timer_wait) | sys.format_time(lock_time) | +----------+--------------+----------------------+---------------------------------------------------+--------------------+-----------------------------+----------------------------+ | 105 | 388 | statement/sql/select | SELECT sys.ps_thread_id(NULL) | TRANSACTION | 9.53 ms | 4.67 ms | | 393 | 659 | statement/sql/select | SELECT a, b FROM t1 ORDER BY a LIMIT 1 FOR UPDATE | TRANSACTION | 8.00 s | 7.99 s | | 664 | 690 | statement/sql/commit | COMMIT | TRANSACTION | 509.89 us | 0 ps | +----------+--------------+----------------------+---------------------------------------------------+--------------------+-----------------------------+----------------------------+ 3 rows in set (0.03 sec)
nesting_event_idで引っ張ってこれました。 timer_waitから実行にかかった時間がわかり、lock_timeからロックの時間がわかります。 今回の場合2行目がlock_timeが比較的大きいので何かしらの原因でロック待ちをしていたことがトランザクション全体の実行時間を長くする原因であることが分かりました。
とりあえず今回の目標である過去のセッションによるトランザクションを追うことが可能だと分かりました。
おまけ どの処理で時間がかかっているのか調べてみる
ついでなのでもう少し踏み込んで、この処理がどのステージで時間がかかっているので調べてみます。
利用するテーブルはp_s.events_stages_history_longです。
mysql80-root@localhost:p_s >select event_name,source,sys.format_time(timer_wait) from events_stages_history_long where thread_id = 53 and nesting_event_id = 393 order by event_id; +-------------------------------------------+----------------------------------+-----------------------------+ | EVENT_NAME | SOURCE | sys.format_time(timer_wait) | +-------------------------------------------+----------------------------------+-----------------------------+ | stage/sql/starting | init_net_server_extension.cc:101 | 446.80 us | | stage/sql/checking permissions | sql_authorization.cc:2176 | 19.08 us | | stage/sql/checking permissions | sql_authorization.cc:2176 | 45.03 us | | stage/sql/Opening tables | sql_base.cc:5591 | 123.20 us | | stage/sql/Waiting for table metadata lock | mdl.cc:1802 | 7.99 s | | stage/sql/Opening tables | mdl.cc:1831 | 1.23 ms | | stage/sql/init | sql_select.cc:677 | 23.80 us | | stage/sql/System lock | lock.cc:331 | 56.06 us | | stage/sql/optimizing | sql_optimizer.cc:282 | 13.54 us | | stage/sql/statistics | sql_optimizer.cc:502 | 54.28 us | | stage/sql/preparing | sql_optimizer.cc:583 | 138.20 us | | stage/sql/executing | sql_union.cc:1409 | 4.14 ms | | stage/sql/end | sql_select.cc:730 | 9.99 us | | stage/sql/query end | sql_parse.cc:4606 | 12.28 us | | stage/sql/waiting for handler commit | handler.cc:1589 | 44.31 us | | stage/sql/closing tables | sql_parse.cc:4657 | 64.98 us | | stage/sql/freeing items | sql_parse.cc:5330 | 61.09 us | | stage/sql/cleaning up | sql_parse.cc:2184 | 4.11 us | +-------------------------------------------+----------------------------------+-----------------------------+ 18 rows in set (0.05 sec)
p_s.events_statements_history_longのevent_idをp_s.events_stages_history_longのnesting_event_idとして探せば良いようです。
とりあえず上記の結果からstage/sql/Waiting for table metadata lockが一番時間がかかっていることがわかります。
（これを使えばshow profileみたいなことができそうですね）
まとめ
ということで、過去(すでにセッションが閉じてしまっている)のトランザクションについてはp_s.events_transactions_history_longから探せることが分かりました。
次回のエントリで過去3回にわたって検証してきた内容を整理します。
