MySQL5.6以前でmetadata lock発生の犯人を後追いする

大事な機構「metadata lock」

MySQL5.5.3から導入された「metadata lock」。

その目的は、
「トランザクション実行中に触ったテーブルについて、DDLによるテーブル構成情報の変更から守る」
ということ。

そうしないと、ロールバックしようとしたら「テーブルがDropされた！カラムが増えた/減った！、どうしたらいいのよ、このレコード！」とかいうことが発生してしまうから。

公式ドキュメント的には、こちらです。
MySQL :: MySQL 5.6 リファレンスマニュアル :: 8.10.4 メタデータのロック

面倒くさい、「metadeta lock」

トランザクションの最中に、「SELECT」しかしていないテーブルも、metadeta lockを掴んでしまう、ということ。

よくネットで叩かれている「DBViewer」、定義情報を参照しただけでも、裏でトランザクションが開始されるらしく、metadata lock掴みっぱなし、ってことに。
DBViewerのこの挙動、直したかどうかは確認していないですけど、こういうGUIツールは、起動してとある画面を確認したら開きっぱなしでしばらく放置とかよくやるので、結構怖いです。

CUIを叩いて作業する場合、意図的にトランザクションを始めることってそんなにないですよね。

だとすると、プログラムのどこかで、トランザクションを開放し忘れている、あるいは、不必要に長いトランザクションを保持しているロジックがある、という疑いが濃厚です。

「metadata lock」によって、何が引き起こされるか

冒頭で触れたとおり、metadata lockされているテーブルには、DDLから保護されるので、DDLが発行できません。

DDLを発行しようとしたセッションについて「SHOW PROCESSLIST」で確認すると「Waiting for Table metadata lock ...」となります。

metadata lockが開放されるまで、DDLを投げたセッションはずっと待たされます。（タイムアウトあり）

この状態＝「Waiting for Table metadata lock ...」があるところに、さらに別のトランザクションが同じテーブルにDMLを発行すると、そちらのセッションも「Waiting for Table metadata lock ...」になります。

この問題が面倒くさいのは、以下の2点。
・引き金を引くのは、DDL。ただし、原因は、そのDDLより先にテーブルを掴んだセッション。
・どのセッションが、どのテーブルのmetadata lockを掴んでいるかを確認できるテーブル等はない。
・先にテーブルを掴んだセッションは、トランザクションはACTIVEだけど、Query処理中とは限らず、Sleepであっても発生する（むしろ、そうなっていることの方が多い）

「詳解MySQL5.7」で、奥野さんが

MySQL5.6までのバージョンでは、取得済みのテーブルロックの情報や、メタデータロックの情報を取得できなかった

と書いた通り、どのセッションがどのテーブルのmetadata lockを掴んでるかはわからない状態で、犯人探しをしなければいけません。

ネットに上がっている情報は、発生時点での対症療法ばかり

ちょっとググって見つかるのは「SHOW PROCESSLIST」して「Sleep」なセッションを1つずつ殺していけば犯人はわかる！
と言うもの。

確かにその通りなんだけどさ。

運用中のDBのセッション、いくらその時点でSleepだからといって、そんな気安くkillできないっしょ。

後から追跡可能にするには、事前に仕掛けが必要

犯人を完全に特定するには、general_logが必要です。

解消されてしまったmetadata lock問題を調査するには、1分に1回など、定期的に以下の情報を取得、蓄積しておかないと辛いと思います。
・SHOW FULL PROCESSLIST (SELECT * FROM information_schema.processlist)
・SHOW ENGINE INNNODB STATUS
・SELECT * FROM information_schema.innodb_trx

犯人特定の手順

ざっくり、こんな感じになります。

SHOW FULL PROCSSLISTの蓄積結果から、waiting for table metadata lockが発生した時間、解消した時間、対象テーブルを把握
SHOW ENGINE INNNODB STATUSの蓄積結果で、手順1で特定した時間帯に、TRANSACTIONがACTIVEなものを把握
innodb_trxの蓄積結果から、手順2で特定したトランザクションが存在する時間帯を把握し、matadata lock被害者の開始時刻より前～解消時刻まで（被害者側がタイムアウトやセッションkillで諦めた場合は、解消時刻よりも後まで）トランザクションが続いていたセッションを把握
SHOW FULL PROCSSLISTの蓄積結果から、手順3で把握したセッションの接続元IPアドレス、接続ユーザを把握
general_logで、手順3、手順4で把握したセッションの挙動を確認する。

general_logがない場合、具体的にどんな処理でmetadata lockを掴んだかは把握できないと思いますので、犯人となったセッションを特定するまでですね。
（出力しないモードで運用していることのほうが多いと思います）

接続元とユーザまでは特定できますが、同じロジックの多重起動が起こりうるサーバーなどの場合、そのロジック側でのログと突き合わせて対象処理と操作者を特定する必要があるでしょう。

DB側だけでの追跡は、この辺が限界です。

MySQL 5.7以降、どうなるか

Performance_schema.metadata_locksに記録されるらしいです。
MySQL :: MySQL 5.7 Reference Manual :: 23.9.12.1 The metadata_locks Table

まだ手元で試してないので、イメージはこちらの記事（英語）を見てみてください。
Who Holds the Metadata Lock? MySQL 5.7.3 Brings Help | Jesper's MySQL Blog

OBJECT_NAME、OWNER_THREAD_ID、OWNER_EVENT_ID列はあるけど、発生時刻の列がない。。。
そして、現時点のものしか持ってないから、やっぱり定期的に参照してログ出力しておかないと、あとから確認できないっぽい

余談1

そういえば、MySQL8.0のリファレンスが公開されたけど、MySQL 5.7のリファレンスの日本語化ってされてないんだよな。

余談2

蓄積しておきたい情報、AWSでCloudWatchLogsに吸い上げておくと、Management Consoleから検索できてラクだけど、SHOW ENGINE INNNODB STATUSをCloudWatchLogsで検索するのはちょっとツラい。
ほしい情報が、検索キーでヒットした行の数行下にあったりするけど、そういうのできないんだよね。