TL;DR
- yt-healthckeck に
History list length(trx_rseg_history_len) の監視を追加した--history-list-enable=1すると有効になる(そのうちこっちをデフォルトにする…)- MySQL 5.6とそれ以降のみ対応、もう5.5は知らない…
- デフォルトで10万がワーニング、50万をクリティカルにしてたんだけどあっさり食いちぎられた
- その時の確認方法を主に
History list lengthとは（これは SHOW ENGINE INNODB STATUS の出力に載ってる用語、 information_schema.innodb_metrics 的には trx_rseg_history_len という名前で出てくる）「パージされずに残っているUNDOログレコードの数」らしく、主に「トランザクション開始したまま COMMIT も ROLLBACK も QUIT もせずに残ってるコネクション」があると増えていく。
これが伸びるのはデフォルトの REPEATABLE-READ を保証するためなので、ロックの有無には一切関係ない（ロックフリーな SELECT だけしか含まないトランザクションでも、残っている限り降り積もる）
で、まあコイツが伸びていくと無関係なテーブルでも重くなる(UNDOログがバッファプールに占める割合が増えて、バッファプールミスヒットが多くなるから？）ので、コイツを監視する機能をウチで使っている監視スクリプトである yt-healthckeck に搭載した。SHOW ENGINE INNODB STATUS のパースとかはしたくなかったので、MySQL 5.6とそれ以降の information_schema.innodb_metrics に頼り切っている。
mysql80 15> SELECT name, subsystem, comment, count FROM information_schema.innodb_metrics WHERE name = 'trx_rseg_history_len';
+----------------------+-------------+-------------------------------------+---------+
| name | subsystem | comment | count |
+----------------------+-------------+-------------------------------------+---------+
| trx_rseg_history_len | transaction | Length of the TRX_RSEG_HISTORY list | 2695887 |
+----------------------+-------------+-------------------------------------+---------+
1 row in set (0.01 sec)
Nagiosコンパチな作りになっているのでこんな風に検出できる。
$ bin/yt-healthcheck -S /usr/mysql/8.0.22/data/mysql.sock -uroot --history-list-enable=1
CRITICAL on xxxxx: trx_rseg_history_len is 2776982 (master)
$ echo $?
2
と、まあ検出するところまではどうでも良くて、ここから「History listを伸ばしているスレッドを特定して、そいつが KILL しても良さそうなものかダメっぽいか」を確認する方法を考える。
まずは information_schema.innodb_trx から長そうなトランザクションを探す。具体的には trx_started が古そうなヤーツ。
History list lengthを何らかの方法でグラフ化しているのであれば、だいたい「増え始めた時間帯」に開始されたトランザクションが残っていることが多いのではないか。
mysql80 4532569> SELECT * FROM information_schema.innodb_trx ORDER BY trx_started ASC\G
*************************** 1. row ***************************
trx_id: 421499581279640
trx_state: RUNNING
trx_started: 2020-10-22 15:40:04
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 0
trx_mysql_thread_id: 15
trx_query: NULL
trx_operation_state: NULL
trx_tables_in_use: 0
trx_tables_locked: 0
trx_lock_structs: 0
trx_lock_memory_bytes: 1136
trx_rows_locked: 0
trx_rows_modified: 0
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
trx_schedule_weight: NULL
*************************** 2. row ***************************
trx_id: 5909317
trx_state: RUNNING
trx_started: 2020-10-22 18:45:04
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 3
trx_mysql_thread_id: 4558875
trx_query: COMMIT
trx_operation_state: NULL
trx_tables_in_use: 0
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 1136
trx_rows_locked: 1
trx_rows_modified: 1
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 0
trx_is_read_only: 0
trx_autocommit_non_locking: 0
trx_schedule_weight: NULL
2 rows in set (0.08 sec)
ここで手に入れた trx_mysql_thread_id が SHOW PROCESSLIST の ID になる。
mysql80 4532569> SHOW PROCESSLIST;
+---------+-----------------+-----------+--------+---------+-------+----------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+---------+-----------------+-----------+--------+---------+-------+----------------------------+------------------+
| 5 | event_scheduler | localhost | NULL | Daemon | 95512 | Waiting on empty queue | NULL |
| 15 | root | localhost | d1 | Sleep | 745 | | NULL |
| 3300152 | root | localhost | NULL | Sleep | 0 | | NULL |
| 4233344 | root | localhost | d1 | Sleep | 630 | | NULL |
| 4532569 | root | localhost | NULL | Query | 0 | init | SHOW PROCESSLIST |
| 4626846 | root | localhost | sbtest | Query | 0 | waiting for handler commit | COMMIT |
+---------+-----------------+-----------+--------+---------+-------+----------------------------+------------------+
6 rows in set (0.03 sec)
SHOW PROCESSLIST だと接続元IPとポートくらいはわかる（↑は root@localhost だけど…）ので、接続元にログインしてそのポートを使っているプロセスを特定すれば、「何をしていたのか、 KILL して良いのかどうか」はある程度判断が付く鴨。
バッチとかで掴んでいるようなわかりやすい場合はこれだけで何とかなるけど、「GUIなクライアントを開いている間ずっとトランザクションを掴みっぱなしになる」みたいな時は trx_mysql_thread_id を performance_schema.threads で thread_id に変換して performance_schema.events_statements_history から引くのが良い感じだった（バージョンによっては performance_schema.setup_consumers の設定が必要）
過去に発行したクエリーが何となくわかると特定はしやすかった。
ただし、 events_statements_history は直前の10件しか保持しないので、それより前に何をしていたのかはわからない。
mysql80 4532569> SELECT * FROM performance_schema.threads WHERE processlist_id = 15\G
*************************** 1. row ***************************
THREAD_ID: 49
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 15
PROCESSLIST_USER: root
PROCESSLIST_HOST: localhost
PROCESSLIST_DB: d1
PROCESSLIST_COMMAND: Sleep
PROCESSLIST_TIME: 888
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: Socket
THREAD_OS_ID: 29875
RESOURCE_GROUP: USR_default
1 row in set (0.10 sec)
mysql80 4532569> SELECT sql_text FROM performance_schema.events_statements_history WHERE thread_id = 49 ORDER BY timer_start ASC;
+-------------------------------------------------------------------------------------------------------------------+
| sql_text |
+-------------------------------------------------------------------------------------------------------------------+
| SELECT * FROM sbtest.sbtest1 WHERE id = 2 |
| SELECT * FROM sbtest.sbtest1 WHERE id = 2 |
| SELECT * FROM information_schema.innodb_buffer_page LIMIT 1 |
| SELECT table_name, index_name, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1, 2 |
| SELECT table_name, index_name, page_state, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1, 2, 3 |
| SELECT space, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1 |
| SELECT page_type, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1 |
| SELECT * FROM information_scheam.innodb_metrics WHERE name = 'trx_rseg_history_len' |
| SELECT * FROM information_schema.innodb_metrics WHERE name = 'trx_rseg_history_len' |
| SELECT name, subsystem, comment, count FROM information_schema.innodb_metrics WHERE name = 'trx_rseg_history_len' |
+-------------------------------------------------------------------------------------------------------------------+
10 rows in set (0.04 sec)
「そのトランザクションが一度でも UPDATE や INSERT をしたかどうか」というだけなら、 SHOW ENGINE INNODB STATUS の TRANSACTIONS セクションに undo log entries と一緒に現れるかどうかで判断できる。行を更新してコミットしていないなら、必ずUNDOログを抱えているから。
------------
TRANSACTIONS
------------
Trx id counter 6437808
Purge done for trx's n:o < 43475 undo n:o < 0 state: running but idle
History list length 3153058
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421499581282208, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421499581281352, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421499581278784, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421499581277928, not started flushing log
mysql tables in use 1, locked 1
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 6437806, ACTIVE (PREPARED) 0 sec
2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 4819118, OS thread handle 140024457672448, query id 14114909 localhost root waiting for handler commit
COMMIT
おまけ。
トランザクションを生かしたまま、他のスレッドからひたすら UPDATE sbtest.sbtest1 SET k = k + 1 WHERE id = 1 だけを突っ込み続けてHistory list lengthを270万くらいまで伸ばした時のバッファプールの様子。
mysql80 15> SELECT page_type, COUNT(*) FROM information_schema.innodb_buffer_page GROUP BY 1;
+-------------------+----------+
| page_type | COUNT(*) |
+-------------------+----------+
| UNDO_LOG | 5200 |
| UNKNOWN | 1024 |
| INDEX | 1513 |
| SYSTEM | 384 |
| INODE | 57 |
| EXTENT_DESCRIPTOR | 4 |
| IBUF_BITMAP | 4 |
| FILE_SPACE_HEADER | 5 |
| TRX_SYSTEM | 1 |
+-------------------+----------+
9 rows in set (0.12 sec)
半分以上UNDO_LOGに持っていかれてしまった…。
道理でよくミスヒットするわけだ（空っぽのテーブルに対するSELECTでも散発的に10msくらいかかる）
