waiting for metadata lockにもう負けない。GCP CloudSQL上で開きっぱなしのTransactionの探し方。

🎍 あけましておめでとうございます🎍

エンジニアの前原です。

皆さん、年末はいかがお過ごしでしたか？

私ですか？私は12/28の夕方まで障害の原因追求に奔走してました。なんとか年内に調査完了して安堵したのを覚えています。

折角なので今回はその問題について対処法と合わせてご紹介したいと思います。

（暫定的な対処というよりは根本対処のときの調査はこうしようね、という話です。暫定的な対処は mysql process kill とかでググれば色々出るはず。）

サクッと何が書いてあるかというと

MetaDataLock が発生したら CloudLogging を利用して CloudSQL のログ(general_log)を参照し、MetaDataLock の引き金となっているクエリの特定の後、サービスの発行するトランザクション処理の閉じ忘れを修正し、トランザクションの滞留を解決してからマイグレーションを再実行してください。

何が起こったのかというと

以下の流れで DB がロック => サービス停止してしまいました。（ご迷惑おかけしました。）

アプリが発行するトランザクションに閉じ忘れがありました（commit も rollback もされていなかった）
マイグレーション(onlineDDL)を実施しました
2 のマイグレーションが 1 で発行された滞留しているトランザクション（onlineDDLの対象となるテーブルを参照中）を待機します(onlineDDL の制約による)
以降のクエリがマイグレーションを待機します(waiting for metadata lock です)
DB のメモリ逼迫、サービスの停止が発生しました

環境は

CloudSQL(MySQL 5.7): 普通の MySQL です。
sequelize v4.41: JS 製の ORM です。（バージョンが古いのでそろそろアップデートしたい。）

解決の前提として

CloudLogging（GCPのLog管理基盤サービス）でログを参照できる必要があります。参照するためには以下のフラグの設定が必要です。

general_log : ON
output_logs : FILE

（general_log は本当にあったほうがいいです。デフォルトだと OFF です。）

原因は

まず、マイグレーションが停止した原因は

Metadata Lock が働いたからでした。

マイグレーション処理(onlineDDL)は現在動いているトランザクション内で参照されているテーブルについて実行することができません。

そして Transaction が滞留していた原因は

transaction 処理の閉じ忘れが原因でした。

この閉じ忘れ箇所を探すのに苦労しました。（が、ログを見れば一発でした。。）

解決手順はこちら

information_schema.innodb_trx を参照して滞留しているトランザクションの trx_mysql_thread_id を記録

問題の発生しているDBへアクセスして USE information_schema; SELECT trx_mysql_thread_id FROM innodb_trx; で確認できると思います。特に設定を変更していなければ今回のようなケースのトランザクションは interactive_timeout の値の影響で8時間でタイムアウトしてしまうと思うので早めに確認することを推奨します。
手順１で調べた trx_mysql_thread_id を含むログを Cloud Logging に残された DB インスタンスのログから抽出する

ログエクスプローラの使用から使い方を確認できます。GUI ポチポチしててもなんとかなる印象です。
抽出したログ内の SQL からアプリケーション側での transaction 処理の閉じ漏れを探し修正する

コレが結構サービスによっては面倒かもしれないです。今回のケースでは、クエリが呼び出しているカラムをヒントに探してゆきました。
再度マイグレーションを実行する

マイグレーション実行前に 1 のクエリでトランザクションが滞留していないか今一度確認しましょう。
解決

~~俺たちの戦いはこれからだ~~