PythonでMySQLのLockWaitクエリを採取

データベースには処理の一貫性を保つためのトランザクションという仕組みがあり、扱うデータ箇所がカチ合う場合に、後発のクエリが待機状態になることがあります。

その待機がどのくらい発生しているかは、DBのステータス値やメトリクスから判断できるのですが、ではどのようなクエリで発生しているかとなると、調べるのが面倒くさい。というところから発生したPythonスクリプトになります。



LockWaitを調べる理由

そもそも私の業界のWEBアプリケーションの場合、クエリがロック解除待ちを長時間することはほぼありません。スロークエリを撲滅させるのと同じで、1クエリに0.5秒以上とか必要としちゃうと、ユーザーへのレスポンスとしては容易に1秒以上になって、ユーザー離れの要因になるため許容できないからです。

しかし複数のサービスを観察していると、LockWaitの発生頻度が結構違ったりして、それはまぁアプリケーションの仕組みやトランザクションを適切に扱えているかで異なるのでいいんですが(よくない時もある)。

サービスが慢性的に重いとか、特定のタイミングで重さやエラーが顕著になる、といった現象の場合に、LockWaitのメトリクス値が高めの場合は、原因調査の一つとしてやはり調べざるを得ません。

そのようにガツンと直したい時、または慢性的な発生を改善したい時に、原因となっているクエリを知るために必要となります。


既存の調査方法

MySQL 5.x だと INFORMATION_SCHEMA にロック関係の情報はあって、8.x は performance_schema も合わせて使えば情報としては足りることになっているのですが、わざわざ直にテーブルを見なくとも、innotop を使えばイィ感じに結合したデータを見ることができます。

具体的には innotop のこの辺のコードを見たほうが早いです。ツールとしてはいろんな機能があるのですが、今回に関してはここだけで十分。

情報系テーブルのドキュメントはこれら。


他に、スロークエリログにも Lock_time という記録があるので使えそうですが、実は最初のロック獲得までの時間はこれに含まれていないので、頼ることはできません。



Pythonで書く理由

ウチの監視システムの一部はPython3で書いているので、自動的な定期採取にするためにPythonで書きました。

肝心のロック情報取得クエリは innotop からパクっインスパイアかつ少々手を加え、それを定期的に実行させて、全WriterRDSから採取し、結果をS3に保存して、独自の管理画面で見れるようにしました。

ただ、これだとごく決まったタイミングでの瞬間的なサンプルデータみたいな類のモノになります。日々程度を確認しやすいという意味では、こういう自動化は必要ですが、それとは別に深堀り調査するためのスクリプトも必要だと思いました。

今回のは、その定期実行Lambda用フレームワークで書いたものから、抜き出してペライチのスクリプトに起こしたものになります(ペラ2だけど)。


LockWait採取Pythonスクリプト

別に勿体ぶるものでもないですが、Gistに載せてあります。


データ採取 (lockwait_watcher.py)

Python3 と pip の mysqlclient が必要なので、そのインストールをし、

lockwait_watcher.py の Config 部分でMySQL接続情報を編集し、実行します。

たいてい何も残りませんが、本番で何度も実行したり、テスト環境でわざとロック待機を発生させた状態で実行すると、DATA_DIR にファイルが保存されます。この結果データは、1実行ごとに1ファイルになり、複数を残しても大丈夫です。

動作確認できたら、PERIOD_SEC を数十秒に編集し、ガツンとログ採取していきます。

1つ注意点として、AWS RDSで 8.x の場合は performance_schema がデフォ OFF になっているはずなので、ON にしてあげないとエラーになります。

データ集計 (lockwait_counter.py)

結果データがある状態で、もう1つのスクリプトを実行します。

DATA_DIRのデータを全部集計するので、複数DBがある場合は、別サーバー分の採取データをまとめていれて実行することで、サービス全体の結果とすることもできます。

こちらは集計結果をそのまま標準出力しています。こんな感じ。

所詮、1秒間隔の採取なので、サンプリングであることに変わりないですが、間隔を短くしたり長く採取すれば、それだけデータの信頼度も上がるので、そのへんはお好みです。


結果データの感想戦

概ね当初閃いた想定通りの結果は出たのですが、いくつか要所の感想を述べておきます。

ブロッククエリ

まずブロック側のクエリが必ずしも記録されるわけではない、ということです。

なんせ多くは瞬間的な出来事ですので、取得した瞬間にブロッククエリの実行は終わっていて、SLEEP状態または次のクエリやCOMMITになっていることがあります。

この場合、アプリケーションコードや仕様を確認しつつ、の確認を必要とするかもしれませんが、まぁ開発者自身がみればだいたい予想つくでしょう。

時間の記録

ロック待機時間の合計 WaitTotalTime
ロック待機時間の最小・最大とした WaitSecs
ブロック側クエリのトランザクション時間の最小・最大 BlockAge

これらの数値は残念ながら、整数値での記録なので全然正確じゃありません。ほとんどが 0 ですし、1 だとしても日時が 01:23:34.99 から 01:23:35.00 の記録でも 1 になるからです。

元データにFloat時間がなくてどうしようもなく、参考程度の存在でショボンヌ。

TablesLocked

名前からするとテーブルロックが発生してそうですが、別物です。なんとなく出しちゃいましたが……

INFORMATION_SCHEMA INNODB_TRX テーブル の TRX_TABLES_LOCKED を参照してください。

重複ロック

A が B をブロックしたら1ロックですが、
A が B と C をブロックしたら3ロックになります。

クエリで書くとこんな感じ。

結果からの読み取りには微々たる影響の話ですが、一応。


感想戦

最近は、作業がめんどくせぇ!って感じた瞬間にコーディングと自動化で解決することを心がけています。

今回はふと考えはじめてから、最初は超古いスレ(How can I show mysql locks?)を見て、次に innotop の実装を見たら教科書だったので一気に楽になり、あとは集計するためのデータ構成を考えるだけでした。

1秒単位で採取するとしても、もし長いトランザクションがあれば同じデータを取得することになるので、そこの区別をどうつけるかは考えましたが、駆け足コーディングしたので100%正しいかは微妙……一応本番での採取データが大丈夫そうなのは確認したけど……あとで直すかもしれない。自分、DBAじゃないんで自信ないナリ……

あとはどういうファイル構成にするかくらいで、今回は2枚。スクリプトとしてはペライチの方が扱いやすい場合もあるかもだけど、最近は採取と集計がある場合は分けることにしています。

一気に処理しちゃうと、集計失敗した時に採取からやり直しとか、集計対象の柔軟性が落ちるとか、不便なことのほうが多いからです。あと1枚の中で引数で役割分けるのも、汚らしくなりますしね。



という感じで、楽しいPythonのお時間が終わってしまいました;-)

どれくらい役立つかはわからんけど、この先のトランザクションの精査の方が本番だし面倒なんですよ。ちょっと面倒度合いが減っただけに過ぎぬのだ!(クワッ