けんちゃんくんさんの乱とはなんだったのか
mod_mruby ngx_mruby Advent Calendar 2017の記事を書きます。内容は僕が12月の初旬に格闘していたくんさんレンタルについてです。
僕の今日は「くんさんレンタル」に捧げたといっても過言ではない。
— P山 (@pyama86) December 7, 2017
今日は俺がくんさんレンタルを倒す。
— P山 (@pyama86) December 8, 2017
だいぶ追い詰めたけど今日もくんさんレンタルを捉えることはできませんでした。
— P山 (@pyama86) December 8, 2017
なお、無事、収束しているので変ではなく乱として扱います。変と乱の違いは下記を参照ください。
"変"だと、その行動による改革が成功したことになるので、負けていないぞという気持ちがあるのであれば "乱" が適当でしょう
— モノクロメガネ研究員 (@monochromegane) November 28, 2017
nginxのtracとしてはこのあたりが近いと思います。
乱の詳細
ペパボのEC事業部のケンちゃんくんさんがロリポップマネージドクラウド上でサービスを開始したくんさんレンタルのサイト描画が正常に行われない場合があるというのが初期症状でした。
ブラウザのデバッガーを利用するとこのように、jsや画像資産が正常にダウンロード出来ていないことが確認できました。
jsや画像系で起きていたのでHTTP/2のサーバプッシュを疑ったのですが、特にそういった設定は入っていなかったため、次に、ストリームの不具合を疑い、nginxのhttp2_max_concurrent_streamsに1を設定してみました。
すると問題なく表示がされたので、被疑がHTTP/2に移ります。この段階でHTTP/2を利用しなければ問題ないことは確定ではあったので、本番サーバでは一時的にHTTP/2を無効にしました。
次に状況を再現し、デバッグするためにdocker-composeを利用して、諸々の環境を準備し、手元で実行したところ全く症状が起きないことがわかりました。
本番環境と手元の環境の差異を考えてみると、クライアントとサーバのNW距離と、それに比例するNWレイテンシが考えられます。
その仮説に基づき、下記のパラメーターのチューニングを行いました。(一部)
- net.ipv4.tcp_tw_reuse
- net.ipv4.tcp_rmem
- net.ipv4.tcp_wmem
- net.core.rmem_max
- net.core.wmem_max
しかし、スループットに多少の変化はあったものの、不安定な状況は改善しませんでした。次に被疑に考えたのはngx_mrubyのフックポイントです。この症状が起きる前にmruby_output_header_filter
を利用して、レスポンスの直前にある処理を行うというフックを追加していました。このフックを利用することでレスポンスの処理がブロックされることになるので、そこが一つ何か問題を起こしているのではないかと考えました。
そこで試しに、フックポイントをmruby_output_header_filter
からmruby_output_body_filter
へ変更したところ、問題なくコンテンツが表示されるようになったため、この時点でmruby_output_header_filter
が原因だとこの時点で断定しました。
勝った。理屈ありで勝ったから本当に勝ったかもしれない。
— P山 (@pyama86) December 12, 2017
後に、問題はこれだけでは解決せず、最終的にはmruby_log_handler
のフックを利用することになりました。
これらのことからHTTP/2とngx_mrubyを利用した場合に、output_filterで何か問題がありそうだと思って、先程まで環境を粛々と作っておったのですが、手元の環境では再現すらせず、完全に詰んでいました・・・
おそらく、HTTP/2 + ngx_mruby + NWレイテンシなのかなぁ・・・とぼやっとは思っているものの、今日中に環境作るのがあれだったのでひとまず記事を書いてみました。今日はいよいよクリスマス・イブですね!明日はペパボのアドカレの担当なので皆様また明日お会いしましょう?