キャッシュライブラリのスレッドイシューで頑張った話
まとめ
以下の issue リンクを見てください。
github.com- Caffeine 使用者は早く2.6.1-snapshot にした方がいいかも
以下本文
最近あるサーバが古いデータを返してるという現像があり、最近自分がその付近のコードをいじってたので、自分の変更の原因かを調べながら、ローカル再現とか頑張って、全部で一週間ぐらいかかって、最後は多分キャッシュライブラリの問題じゃない?まで行き着いた記録です。
自分が使ってたのは Caffeine という高パフォーマンスなキャッシュライブラリです。使い方は簡単で、以下のような感じでデータをキャッシュ後にもし2分半後にアクセスが来た場合、キャッシュデータを戻しながら、非同期アクセスを始める;又は5分後にアクセスが来た場合、キャッシュデータは失効されてるので、新しく非同期アクセスを初めて、クライアントはそのリクエストの CompletableFuture
を利用する形です。
Caffeine.newBuilder() .refreshAfterWrite(300 / 2, TimeUnit.SECONDS) .expireAfterWrite(300, TimeUnit.SECONDS) .maximumSize(cacheSize) .buildAsync((key, ignored) -> getFromRemote(key))
初めはもしかしたら getFromRemote
に問題あるんじゃない?と疑って調べたが、実際他のサーバの同キーのデータは正常だし、再起動したら治ってるので、すぐメモリキャッシュの問題かな?につきました。
古いデータがキャッシュ内にあるので、何か手がかりが必要ならヒープダンプ見るしか無いかな、と面倒くさいと思いながら問題データの参照を見ながら発見したのがキャッシュエントリーの writeTime
が他の正常データの writeTime
とすごく離れてるのを気づきました。正常データの writeTime
は 33948135258891076
とその上下なのに、以下のように -9189666743569861076
な数値があった。
ソースコードを追ってみて、setWriteTime
を呼んでいるところを探してみたら、以下のコードがありました。
// Ensure that in-flight async computation cannot expire (reset on a completion callback) if (isComputingAsync(node)) { synchronized (node) { if (!Async.isReady((CompletableFuture<?>) node.getValue())) { long expirationTime = expirationTicker().read() + Long.MAX_VALUE; setVariableTime(node, expirationTime); setAccessTime(node, expirationTime); setWriteTime(node, expirationTime); } } }
データを非同期取ってる時に失効されないように時間を未来に設定していた。なので問題データと正常データを計算してみて、2日ぐらい前の時間で Long.MAX_VALUE
を足してた数値が出て、もう既に2日以上キャッシュされていたのがわかった。-9189666743569861076 - Long.MAX_VALUE = 33705293284914733
、なので (33948247-33705293)/60/60/24 = 2.x
ぐらい。
ただコードのコメントで言ってる通り、完了のコールバックで元に戻すと書いてるが、何かの問題で戻ってないかも?
その後デバッグモードで調べたら、コールバックは LocalAsyncLoadingCache#getにありました。
コード自体見てみると AddTask#run
と LocalAsyncLoadingCache#get
のコールバックは並行で実行されるんじゃない?といろいろ調べたらちゃんと BoundedLocalCache#replace
で synchronized を使っていました。
なので並行のシナリオ的に2つ:
AddTask#run
のsynchronized
に入った後、writeTime
を未来にして、その後BoundedLocalCache#replace
で現在の nanoTime にする。ここでのhasExpire
1 と 2の判断も合理(実はここが問題)に見える、now - node.getWriteTime() >= expiresAfterWriteNanos()
は 現在を未来(現在 +Long.MAX_VALUE
)で引くとネガティブな数値になる。先に
BoundedLocalCache#replace
内の後処理を完了した場合、既にwhenComplete
に入ってるのが分かるため、if (!Async.isReady((CompletableFuture<?>) node.getValue()))
はfalse
になるので、未来時間を書き込まない。
なので問題がなさそうなので、次はそろそろ自分の見落としか、JVM のバグかなと。丁度最近同僚と System#nanoTime
はマルチスレッド/コアで安全かの話題があり、昔 Windows でコア違いで nanoTime
がまさかの end - start がマイナスの値になるとかを見た記憶が。
java - Is System.nanoTime() completely useless? - Stack Overflow
ただこれは超昔な情報だし、Linux 上でも聞いた事ないが、もうなんでもいいから試そうと思ってヤケクソでサンプル書いたが、色々試しても再現できない。もうだめだと思って、この機にもう一回時間付近のコードを調べたら、現在時間の now
を取るコードが BoundedLocalCache#replace
では synchronized
の外にあった。
こうなるともし AddTask
の synchronized
に入った後、先に BoundedLocalCache#replace
内が now(ここで0とする) を取得した後、AddTask
内が now(ここで10とする) を取って Long.MAX_VALUE
を足して writeTime を 10 + Long.MAX_VALUE
にする。その後 BoundedLocalCache#replace
が synchronized
に入ったら、 0 - (10 + Long.MAX_VALUE)
になるので、とてもでかい値になり、 hasExpire
が true
になって、元のコールバックリセットに失敗するシナリオになってしまう。
ただ全て想像上なので、どう再現するか悩んだ後、IDE のデバッグを使えばいいじゃんと思いだした。デバッグで Thread 毎停止(Suspend Thread)と、Evaluation and log はスレッドイシューに大変使える!
なので上の AddTask#run
と BoundedLocalCache#replace
でブレークポイントを設定して、交互に実行しながら再現できたので、開発者に教えて修正してもらった。キャッシュでデータが失効できないのはかなりやばいので、使っている方は早く snapshot でも良いからアップデートしたほうが良いかも。