こんにちは、@color_boxです。 仕事中に見つかったちょっとした問題とその解決の道程について書いてみようかと思います。
どなたかの参考になれば幸いです。
問題概要
デプロイ直後のRailsアプリで問題が発生。 アプリへの特定のアクセスが極端に遅いが、一定時間経つと直る という内容。
問題となっていた箇所はarticle/editといったごく普通のeditアクションで、アクセスしてみても普通にレスポンスが返ってきます。
報告直後は特におかしくは見えないため一旦保留することにしました。
その後、デプロイ直後にのみ当該アクション遅くなるということに気が付きます。
その問題発生時は通常1,000msかからないようなアクションが何故か8,000msかかるという状態になっていました。
調査の流れ
問題とその再現方法が判明したので、なぜこれが起こっているのかを調査します。
下記のようなことを試しても特に改善できなかったため、何が原因なのかがわからず悩みました。
- rack-mini-profilerを導入しボトルネックを探る
- 直近で導入した影響を与えていそうなgemを消す
そんな時「システムコールのログをみると何か見つかるかもしれませんね」
という助言を頂いたのでそこから何が起きているかを見ることに。
straceでUnicornのプロセスを監視しながらアクセス。
すると、straceのログから同名で拡張子の異なる多数のファイルにアクセスしている形跡が見つかりました。
articles/_edit_.ja.js+.raw articles/_edit_.ja.js+.erb articles/_edit_.ja.js+.html articles/_edit_.ja.js+.builder ...
(このようなファイルへのアクセスログが数千行続く)
また、動作が遅くなっていたeditアクションにはedit.js.erbとedit.html.hamlの2つのビューファイルが存在しています。
以上から、
アクションにアクセスする際にeditのみを渡していると、Railsがedit.js.erbとedit.html.hamlのどちらにアクセスすべきなのか特定できず、ファイルの拡張子を探すために時間がかかってしまう
のではないかと推測しました。
つまり、アクセス時のアクションの拡張子を指定することで、時間のかかっている探索処理を短時間で終わらせることができるのはと考えられます。
最終的に下記のような修正を適用したところ、初回アクセス時に要する時間が 4010ms から 569ms へと大幅に短縮でき、おおよそ7倍ほど高速化されました。
- link_to '編集', edit_article_path, remote: true + link_to '編集', edit_article_path(format: :js), remote: true
まとめ
(Rails 5.2を使用している場合は)ある一つのコントローラ下にある1アクションで複数の形式を扱う時はlink_toにformatオプション指定をつけよう。
edit.js.erb edit.html.haml
ちなみに、この問題はRails 6.0では解決済みなので、Rails 6.0を使用している場合は特に対策は必要ありません。
また、この問題は初回アクセス時のみ発生する問題であるため、そこまで大きな問題にはなりにくいです。
参考
掘り下げ
さて、ここまでが今回仕事で直面した問題の判明と解決なのですが、どうせならもう少し問題を掘り下げてみようと思います。
結論から言うと、この問題は既に下記PRで解決済みです。 具体的に何が起こっていたか、どのように解決したかについてはPRをご参照ください。
また、この修正はRails 6.0には導入済みですが、Rails 5.2には導入されていません。
今回はRails 5.2を使用していたため、このPRで解決された問題が発生していたというわけです。
目玉となるような大きな機能追加だけでなく、こういった細かい改善もどんどん盛り込まれていくので、可能な限りRailsのバージョンは追従していきたいですね。
