Lettuce の スレッドイシュー で頑張った話

まとめ

• 以下の issue リンクを見てください。
  github.com

• 同じく IDE の デバッグモードで Thread 別の停止を使えば Threading issue を再現しやすい

• Lettuce で Request queue size exceeded を継続的にみかけたら多分これだよ、新しいバージョンにするか再起動で対応

以下本文

去年から数ヶ月に一回サーバ群中のいち台が OOM を発生することがあった、OOM なら迷わず heap dump なので、dump してみたら redis connection の command buffer に command が超溜め込んでいる事が見つかった。

初めの対応は開発者の言う通り、先に command quene のサイズを制限して OOM 回避ぐらいしてみた。しかしその後またまた OOM、コードを見てみると queue のサイズチェックにミスって assert があったので、assert を取る PR 作ったら何故か作者が command buffer の作り直しがw、一応この修正で OOM はもう発生しない。

後は開発者が command 貯まる理由は connection が途切れた場合、再度接続するまで貯まるのを聞いて調べてみたら、ConnectionWatchdog が再接続をしているのが見つかった。ここで変なのが ConnectionWatchdog の接続 timer タスクが既に過ぎてるのに(expired)、何故か connection 関連のフィールドが null のままだった。

実際 lettuce は netty を使っていたので、新しいスレッドを作らない限り、同じチャンネルのメソッドコールは全て netty スレッドで問題はないと思って調べたら、再度接続のところが netty の Timer だった。

色々スレッドの順番を脳内想像して、多分問題は Timer の使い方だなと思ってきた。コードを見てみると、this.reconnectScheduleTimeout を使って再接続の重複を防止している、ただ reconnectScheduleTimeout のアサインはタスクを作った後なので、GC の pause とかでもしかしたらアサインする前に既に Timer#newTimeout のブロックが先に実行される可能性があるかなと。実際元のコードの想定では Timer#newTimeout → this.reconnectScheduleTimeout のアサイン → Timer task が timeout して実行後 this.reconnectScheduleTimeout を null にすると思いますが。前述の通り、もし先に timer task が先に実行されると、this.reconnectScheduleTimeout は永遠に null にならないので、次回の再接続で止まってしまう。

this.reconnectScheduleTimeout = timer.newTimeout(it -> {
    if (!isEventLoopGroupActive()) {
        logger.debug("isEventLoopGroupActive() == false");
        return;
    }

    reconnectWorkers.submit(() -> {
         ConnectionWatchdog.this.run(it);
         return null;
    });
}, timeout, TimeUnit.MILLISECONDS);

ただこういうケースは稀すぎて、実際自分の環境でも数十〜百台で２，３ヶ月で一台が発生するので、テスト環境でロードを追加して回してもなかなか再現できない（ログを追加して、想定シナリオになってるかどうかを試してみたかった）。最後はやっぱり IDE のデバッグモードで HashedWheelTimer#newTimeout の return の一歩手前に thread suspend を使って再現して、可能性がゼロではないのを知って、PR を作って送った。

---

• コードを書く時間が減ってきたので、こういうアウテージ対応でチームに貢献できて良かった
• プロジェクトによって開発者の美感とか設計思想にそって PR 作るの難しいなといつも思う