Published
- 8 min read
RDSでtrx_mysql_thread_idが0のトランザクションが残ってしまったときの対応方法
1.背景
XAトランザクションを利用して作成されたアプリを運用していると、
何かしらの原因でtrx_mysql_thread_idが0のトランザクションが残り続けるといった現象が生じます。
年間1回生じるか生じないかの事例ですが、運用ノウハウのメモがてら記載しておきます。
2.どのような現象が生じるか？
2-1.特定レコードがロックされたままになる
XAトランザクションが残り続けることで、特定レコードの更新ができなくなったりします。
ソーシャルゲームの場合だと、ある特定ユーザの特定のアップデート処理ができなくなり、ユーザがカスタマーサポートへ連絡がきます。
当然、ユーザとしてはゲームが正常に遊べない状態なので、一刻も早くこの状態を解決してあげないと駄目なケースへと発展します。
2-2.SHOW PROCESSLISTで、該当のスレッドを見つけられない
mysql> SHOW PROCESSLIST;
+-----------+----------+---------------------+--------------+---------+------+-------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----------+----------+---------------------+--------------+---------+------+-------+------------------+
| 616400894 | rdsadmin | localhost:16849 | mysql | Sleep | 12 | | NULL |
(snip)RDSのMySQLに対してのSHOW PROCESSLIST実行結果は、上記のようになります。
本来であれば、このようにIDが割り振られた各スレッドの実行状況が見れるのですが、
trx_mysql_thread_idが0になってしまうと、ここにスレッドとして表示されません。
別の確認方法として、SHOW ENGINE INNODB STATUSを実行してみます。
mysql> SHOW ENGINE INNODB STATUS\G
(snip)
------------
TRANSACTIONS
------------
(snip)
---TRANSACTION 49685730342, ACTIVE (PREPARED) 6295472 sec recovered trx
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 2
(snip)すると、TRANSACTIONS項目の欄に、あるトランザクションが6,295,472secも残り続けていることが確認できます。
詳細なトランザクション情報を取得するため、information_schemaデータベース内のinnodb_trxのテーブルを確認して、実行中のトランザクションを確認します。
mysql> SELECT * FROM information_schema.innodb_trx\G
(snip)
*************************** 2. row ***************************
trx_id: 49685730342
trx_state: RUNNING
trx_started: XXXXX-XX-XX XX:XX:XX(XXは実行開始時間)
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 3
trx_mysql_thread_id: 0
trx_query: NULL
trx_operation_state: NULL
trx_tables_in_use: 0
trx_tables_locked: 0
trx_lock_structs: 1
trx_lock_memory_bytes: 360
trx_rows_locked: 0
trx_rows_modified: 2
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: 10000
trx_is_read_only: 0
trx_autocommit_non_locking: 0
2 rows in set (0.00 sec)すると、このようなtrx_mysql_thread_idが0のトランザクションが残り続けています。
通常であれば、kill Idのようにして、スレッドをkillできるのですが、trx_mysql_thread_idが0のものは、この対応ができません。
2-3.ストレージ減少速度が著しく早くなる
上記のようなtrx_mysql_thread_idが0のトランザクションが残り続けると、CloudWatchのFreeStorageSpaceがどんどん減り続けてしまいます。
RDSインスタンスの内部の調査はできないので、AWSのサポートへ調査をお願いすると、以下の様な調査結果が返ってきました。
- インスタンスAと他のインスタンスの差分で一番大きいのは、InnoDBの共有テーブルスペースとして利用されるibdata1ファイル
- 共有テーブルスペースはUNDO logsやdouble write buffer、data dictionary などとして利用される
- 変更量の大きいトランザクションを過去に実行した場合には、UNDO 領域を大きく確保するため肥大化することが多い
参考として教えていただいたのが、以下のURL
- Why is the ibdata1 file continuously growing in MySQL?
- [MySQL ibdata1が肥大化する理由(記事の意訳)【日本語訳】]（リンク切れ）
今回の場合、記事の内容のここに該当する。
トランザクションが開始されたことによって、一貫性を提供するために古いページをUNDOに保持しておく必要があるので、InnoDBがデータのスナップショットを作ったということ意味する。もし、データベースに大量の書き込みが行われているのであれば、多くのUNDOページが格納されるということを意味する。
AWSの問い合わせ結果をもとに、異常にidbata1のファイルが膨れ上がっているのがわかったので、
後はこの古いクエリをロールバックしてあげればよい。
3.対応方法
13.3.7.1 XA Transaction SQL Syntaxのユーザコメントに記載されている通りにロールバックを行う。
mysql> xa recover;
+----------+--------------+--------------+--------------------------------------+
| formatID | gtrid_length | bqual_length | data |
+----------+--------------+--------------+--------------------------------------+
| 1 | 36 | 0 | 13ad43ad-764b-4752-81ee-22ff14ee0307 |
+----------+--------------+--------------+--------------------------------------+
1 row in set (0.00 sec)でxidを確認した後、
mysql> xa rollback '13ad43ad-764b-4752-81ee-22ff14ee0307';でロールバックを行う。
なお、2ヶ月ほど残り続けたクエリをロールバックした場合、下記のCloudWatchのグラフのように、
ストレージへの負荷が2時間ほど高くなり、RDSのCPU負荷が10%ほど高くなるので、ロールバックする時間帯は調整しておいた方がよいです。
なお、このトランザクションをロールバックしても、ibdata1のファイルが膨れ上がったのは解消されないため、Free Storage Spaceは回復しません。
減少速度が落ち着くだけです(´・ω・｀)
4.まとめ
このようなtrx_mysql_thread_idが0のトランザクションが残る原因としては、
RDSのフェイルオーバーのタイミングもあったりしますし、EC2 - RDS間の瞬断も考えられます。
XAトランザクションが悪いのではなく、こうしたトランザクションが残り続けたときの検知方法や復旧方法が重要なので、
こうしたノウハウを頭の隅に入れておいておけば、監視内容や障害対応に活かせるかなと。
途中の参考URLにも記載されていますが、本番稼働中の膨れ上がったibdata1ファイルを小さくするのは困難なので、
こうした古いクエリが残り続けていないかどうかをチェックしていただければと思います。