うわっ...railsサーバのコード再読み込み遅すぎ?!

https://github.com/rails/rails/issues/42050 に書いていることを書きます

結論

  • 巨大なrailsプロジェクトで reload! の処理時間時間がかかっていませんか?
    • reload!を実行していなくても、開発中のサーバでapp配下のファイルを編集後、サーバのレスポンスが返ってくるまでの時間が長くないですか?
  • 時間がかかっている場合、ボトルネックはroutesの再読み込みですか?そうであれば、 Rails.application.routes.url_helpers のせいで遅くなっている可能性が高いです
  • https://travisofthenorth.com/blog/2017/12/27/rails-urlhelpers に書いている通り、 Rails.application.routes.url_helpers の呼び出しを減らしましょう
  • Rails.application.routes.url_helpers は結果をキャッシュできないなくて実行するごとにオブジェクトを新しく作っているようで、かなり遅い。rails6.1からキャッシュするようになる

はじめに

そこそこ大きなrailsプロジェクトで、app配下のコードを編集後に、開発サーバにリクエストを送ると30秒くらい時間がかかることが何度かあった。効率が悪くて直したい気持ちなった。ファイル変更後に詰まるので、開発中のみで有効な再読み込み周りが原因であることはなんとなくわかるが、具体的にどこがボトルネックなのかわからなかった。特定するぞ。

ログをとる

コードの再読み込みには、middlewareを介してRails::Application::RoutesReloader, ActiveSupport::FileUpdateCheckerが動いている。こいつらを拡張してログを出力すればボトルネックがわかりそうだ。

結構雑ですが、以下のようなコードでログに出力することにした。

if Rails.env.development?
  module ReloadingTimeLogging
    def execute
      time = Benchmark.realtime do
        super
      end

      type =
        case
        when self.class == Rails::Application::RoutesReloader
          :routes_reloader
        when /lib\/rails\/application\/routes_reloader\.rb/ =~ @block.to_s
          :routes_file_update_checker
        when /\/lib\/active_support\/i18n_railtie\.rb/ =~ @block.to_s
          :locale_yamls_file_update_checker
        when /lib\/rails\/application\/finisher\.rb/ =~ @block.to_s
          :apps_file_update_checker
        when /app\/admin\/\*\*/ =~ @glob
          :active_admin_loader
        else
          :unknown
        end

      Rails.logger.debug { "[ReloadingTimeLogging] Reloading #{type} took #{time} seconds" }
    end
  end

  Rails::Application::RoutesReloader.prepend(ReloadingTimeLogging)
  ActiveSupport::FileUpdateChecker.prepend(ReloadingTimeLogging)
end

ログをとったところ、たまに30秒くらい刺さっているのは「routes.rbの再読み込み」ということがわかった。
これらの情報をもとにrailsのissueを調べることにした。
あった https://github.com/rails/rails/issues/42050

そのissueには、Rails.application.routes.url_helpersは呼び出すごとにオブジェクトを生成しまくる実装になってしまっているらしい。
また、rails5.0以降から、app以下のファイルを更新すると、routes.rbも再読み込みするようになった。この変更によって問題が顕著に出るようになったと。

rails6.1からは、Rails.application.routes.url_helpersのメモ化ができているらしい。それまでは、Rails.application.routes.url_helpers の呼び出しを減らすと再読み込みが速くなる、とのこと。
Rails.application.routes.url_helpers の呼び出しを減らすには、 https://travisofthenorth.com/blog/2017/12/27/rails-urlhelpers に書いている通り、singletonモジュールを使うとキャッシュしてくれるので、生で使うよりも高速になる、と。

さて、自分のプロジェクトでも Rails.application.routes.url_helpers を直接呼び出すのをやめたら開発中のコード読み込みが高速化した。最高!
以下のように、クラスでincludeしていると遅くなる原因だったみたいです。

class User < ApplicationRecord
  include Rails.application.routes.url_helpers
end

おわり