キャッシュライブラリのスレッドイシューで頑張った話
まとめ
以下の issue リンクを見てください。
github.com- Caffeine 使用者は早く2.6.1-snapshot にした方がいいかも
以下本文
最近あるサーバが古いデータを返してるという現像があり、最近自分がその付近のコードをいじってたので、自分の変更の原因かを調べながら、ローカル再現とか頑張って、全部で一週間ぐらいかかって、最後は多分キャッシュライブラリの問題じゃない？まで行き着いた記録です。
自分が使ってたのは Caffeine という高パフォーマンスなキャッシュライブラリです。使い方は簡単で、以下のような感じでデータをキャッシュ後にもし２分半後にアクセスが来た場合、キャッシュデータを戻しながら、非同期アクセスを始める；又は５分後にアクセスが来た場合、キャッシュデータは失効されてるので、新しく非同期アクセスを初めて、クライアントはそのリクエストの 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);
}
}
}
データを非同期取ってる時に失効されないように時間を未来に設定していた。なので問題データと正常データを計算してみて、２日ぐらい前の時間で Long.MAX_VALUE を足してた数値が出て、もう既に２日以上キャッシュされていたのがわかった。-9189666743569861076 - Long.MAX_VALUE = 33705293284914733、なので (33948247-33705293)/60/60/24 = 2.xぐらい。
ただコードのコメントで言ってる通り、完了のコールバックで元に戻すと書いてるが、何かの問題で戻ってないかも？
その後デバッグモードで調べたら、コールバックは LocalAsyncLoadingCache#getにありました。
コード自体見てみると AddTask#run と LocalAsyncLoadingCache#get のコールバックは並行で実行されるんじゃない？といろいろ調べたらちゃんと BoundedLocalCache#replace で synchronized を使っていました。
なので並行のシナリオ的に２つ：
AddTask#runのsynchronizedに入った後、writeTimeを未来にして、その後BoundedLocalCache#replaceで現在の nanoTime にする。ここでのhasExpire1 と 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(ここで０とする) を取得した後、AddTask 内が now(ここで１０とする) を取って 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 でも良いからアップデートしたほうが良いかも。
