単純化したコードでロック処理を検証したらハマった話

はじめに

こんにちは、書いてて気持ちが良いelmをひさしぶりに書きたいと思ったら何もかも忘れていてショックだったのでRustでも勉強しようかなと思った fukajun です。ロコガイドでは、メール配信時に特定の理由で送信できなかったアドレスに次回以降送信しないように、バウンス対象を登録するデータベースがあります。直近、このデータベースの負荷が特定の時間帯に高くなることが増えていました。今回は、負荷を改善する中でハマったことについての話を書きたいと思います。

何が起きていたか？

調査で、データベースからアドレスを抽出してブラックリストを構築する処理が負荷の原因であることがわかりました。その処理はcronから10分に1回起動されるものでした。日々レコード件数が増加していく中で、少し負荷が高まったときにクエリー実行時間が伸びることで、後続の同処理も並走することとなり、結果データベースの負荷を大きくしてしていることがわかりました。これはデータベース側で SHOW FULL PROCESSLIST を実行したときに同じクエリーが走っていることでわかりました。

そこで実際にコードをよく確認すると先頭付近に次の1行が書かれていました。

open(File.expand_path(__FILE__)).flock(File::LOCK_EX)
#              :
# データベースからメールアドレスを抽出してブラックリストを作る処理
#              :

この時点で、分かる人にはわかると思いますが、違和感を感じながらもおっ同時実行を防ぐ処理がすでに実装されている...と思ったのでした。このコード自体は、このスクリプトファイル自身を開いてflockで排他ロックを掛けるコードです。理想的に動いていれば、先に走っているスクリプトがロックを取得しているため、後続のスクリプトはこの行で待つような動作になります。

再現しない動作

とはいえ、実際にデータベースに対して同じクエリーが実行されてしまっているので、手元でちゃんとロックされるか検証してみました。検証したコードは次の内容で実際のデータベースへの処理は何も考えず長い時間かかればいいやと思い sleep に置き換えました。

puts "START"
open(File.expand_path(__FILE__)).flock(File::LOCK_EX)
puts "RUN"
sleep 1800 # データベースのクエリーの代わりに30分待つ
puts "END"

実際に２つを順に動かしてみると先に実行した側のみ RUN と表示され、後に実行した方には、最初に動かした方をkillする、または30分経過させるまで、RUNと表示されませんでした。これについては、手元のMac、実際のサーバー上、両方の環境で試しましたが同様に動作になりました。

再現に成功

その後、同データベースのアラートに対応していた同僚から「これってブロック使わなくていいんですか？」と聞かれることがありました。これをきっかけに最初にコードをみたときの違和感が何だったのかなんとなくわかった気がしたので先程のコードを少し変更して再度試してみました。

puts "START"
open(File.expand_path(__FILE__)).flock(File::LOCK_EX)
puts "RUN"
# データベースのクエリーの代わりに30分待つ
# 追加: なんかメモリー使いそうなことしてみる
1800.times do
  Array.new(1_000_000, "foo" * 1000)
  sleep 1
end
puts "END"

そうなんです！再現するんです！ということでopenしたファイルは変数としても参照されていないことからおそらくGCが関係しているのではと考え、Array.new の部分をGC.start に置き換えての再実行もしてみました。

puts "START"
open(File.expand_path(__FILE__)).flock(File::LOCK_EX)
puts "RUN"
1800.times do
  GC.start
  sleep 1
end
puts "END"

こちらも同様に再現しました。これらの検証から、同様に本番でもデータベースへの問い合わせ中に、GCによってロックが解除されてしまったと考えられます。

ついでに、最初に再現したコードに、GC::Profiler ↗を入れてみて、GCが発生しているかの可視化も行ってみました。 GC::Profiler.report はGCが実行されたあとに実行するとそれまでのGCの実行情報を表示してくれます。

puts "START"
open(File.expand_path(__FILE__)).flock(File::LOCK_EX)
puts "RUN"
# データベースのクエリーの代わりに30分待つ
# 追加: なんかメモリー使いそうなことしてみる
GC::Profiler.enable # 追加: GCプロファイラを有効化
1800.times do
  Array.new(1_000_000, "foo" * 1000)
  GC::Profiler.report # 追加: GCが動作された場合に、実行情報が表示される
  sleep 1
end
puts "END"

このコードを実行すると、ロックが解除された(後続のスクリプトからRUNと表示される)前後でGCのレポートが表示されるため、GCの起動がロックの解除とか深く関わっていることがわかります。

最終的にどうしたか？

これについて、普通そうするだろというツッコミがありそうですが、ファイルオブジェクトが解放されないように、ロックと並列実行させたくない処理をブロックで囲むようにしました。

open(File.expand_path(__FILE__)) do |file|
  file.flock(File::LOCK_EX)
  # 対象の処理
end

まとめ

ロック処理が正しく動くようになったので、並行して同じクエリーが走らなくなりました。結果、問題になっていたデータベースの負荷を下げることができました。

Before

After

気づいてしまえば、たしかにそうかもと思えるようなことでしたが、手元で簡単なコードで試してちゃんと動いたという思い込みのもと、検証しているとなかなか気づかないのでした。試すときのコードがシンプルであることは分かりやすくてよいのですが、実際の環境とは違いがあるということに気をつけたいと思います。あとは、ファイルをオープンするときは、必ずブロックを使おうと思ったのでした。