排他ロックの原因を探る

2019.07.04

こんにちは。
ユニトラストの中山です。

以前Webサービスで中々解決しない問題がありました。
その時実施したインシデント解消にいたる施策やツールのご紹介です。

ミドルウェアのバージョンは記憶が曖昧で申し訳ありませんが以下の通りです。

DB:Microsoft SQL Server 2014
アプリケーションサーバ：Tomcat
Webサーバ：Apache
フレームワーク：Spring、MyBatis

インシデント

システムエラー画面になって動かなくなる。
必ず発生するわけではなく、1ヵ月～2ヵ月毎に発生する。
1人、2人ではなく複数の使用者に同じことが起こっている。
さらに時間をあけてもう一度同じ操作をしても同じ事象が発生する。

原因を探る

まずインシデントが発生した場合、インシデントの解決が優先になります。
本番運用されている場合は業務が止まってしまうのが一番問題です。
これはサーバ再起動で解決しました。
ただ本インシデントは度々発生するため、その度に再起動するのは現実的ではありません。
ここから問題解決を実施していきます。

ログを確認する

まずはアプリケーションログを確認します。
ログを確認するとDBからタイムアウトエラーが飛んできてました。
DB側でタイムアウト起こすような原因がありそうです。
DB側でタイムアウトが起きるのは、別に悪いことではありません。
※システム利用者にとっては使い勝手が悪いですが。

必ず起きるわけではないとこから、使用人数が多くなるときにDB負荷が大きくなり発生すると想定しました。
ただ時間をあけて実施しても同じことが起きていることから、トリガーは使用人数が多いときかもしれませんが、
それが起因でなにかが起きていそうです。

ロックされているテーブルを見つける

タイムアウトが起きているということで、ロック待ちでタイムアウトしているんじゃないかと想定。
インシデント発生時に、現在のロック状況がわかるクエリを投げてもらい、ロックしているテーブルから原因を突き止めようと試みます。

SELECT *
FROM sys.dm_tran_locks
WHERE resource_associated_entity_id
 =(
  SELECT TOP 1 object_id FROM sys.partitions
  WHERE OBJECT_NAME(object_id)='TABLE-NAME'
 );

ロックしているテーブルがわかれば、テーブルから処理が追えるだろうとの想定からです。
ただここからが長かった。

拡張イベントログ使う

SQLServerの拡張イベントログを出します。
拡張イベントはN秒ロックしているセッションをだしたり、デットロックされたセッションを出したりできます。
開発者がDBに直接アクセスできるならプロファイラやレポートで確認してもいいかもしれませんが、
そうでない場合は拡張イベントログが便利です。

結局原因は？

原因は排他ロック（X）が残り、DB・アプリケーション間のコネクションタイムアウトが発生する。
ただ詳細にインシデントをヒアリングするとDB・アプリケーション間のタイムアウトではなく、HTTPのタイムアウトが起きている場合もあるとのこと。
ロック以外の問題もありそうです。
さらにロックされているテーブルに傾向はなく、どの処理でロックされているかなどはわかりませんでした。

インシデント解決手段を探す

原因がわからないからといって、何もしませんでは進みません。
違うアプローチで対処方法を探ります。

リソースを確認する

真因はわかりませんが、「負荷が高いときにリソース不足になっていているのでは？」と仮定します。
JDKにはJavaリソースを監視できるツールがデフォルトではいっています。

・JConsole
メモリやスレッドの状況が確認できます。メモリもNewやOld領域など細かく確認可能です。
今回見たかったTomcat側に設定しているJDBCの設定値も監視できます。
＃DBとどのくらいコネクションはっているかとか

・VisualVM
JConsoleと同じようにメモリなど見れます。

Javaリソースだけでなく他も色々使って確認しましたが、結局メモリもCPUが足りないということはわかりました。
特にCPUはSQLServerが使用しているCPUが足りないということが分かりました。

DBの設定を変える

リソース不足で遅くなるのは仕方がないとして、排他ロックが残るのは別に問題がありそう。
ということでDBの設定情報を変更します。

SQL Serverはデフォルトだとロックエスカレーションという機能があります。
この機能はロックするリソースが多くなった時、行ロックではなくページやテーブルロックしロックリソースを削減します。
状況的にはこれだけでは解消しないと思いますが、発生頻度は下げられるかも。ということでエスカレーションをOFFにします。
ついでに統計情報更新タイミングも深夜に変更します。

セッションKill

インシデントが発生したとき、「SQLServerのセッションをKillすればサーバ再起動しなくても大丈夫ではないか？」
と考え発生時にKillしてみます。
結果はダメでした。アプリで色々問題があり違うエラーが出てしまいます。

トランザクションを見直す

実は排他ロックが残るということでトランザクション回りが一番怪しいのは理解していたのですが、
コードを見直した限り大丈夫との認識でした。
色々手を尽くした後、再度見直してみたら、「エラーログには出ていないが、もしここで例外発生したらトランザクションがクローズされないままになる」箇所が見つかり、念のため対策しました。
結果大当たりでした。

結果

結局以下の2つを実施した後はインシデントが起きなくなりました。
・メモリやCPUを増やした
・見直したトランザクションでアプリを修正した

またHTTPのタイムアウトが起きていた問題ですが、これはDB・アプリケーション間のタイムアウトが起きていないことが原因でした。
なぜかというと、「プロシージャでPrint文を大量に入れているとタイムアウトしないことがある」ということが分かりました。
なぜPrint文を入れるとタイムアウトしないのかは長くなるのでここでは省略いたします。

ここに書いてないことも色々やっていたのですが、かなりのコストと時間を費やしてしまいました。
解決策が見えないとあれこれ手を出して何をやっているのかわからなくなりますが、
そんな時こそ「何をやって何をやっていないのか？」「どのような想定で何を調べているのか？」
を整理して行動、報告しないとお客様は納得してくれないと感じました。

弊社では一緒に働いてくれるメンバー募集中です。ご興味があれば以下バナーから詳しい情報をご覧ください！