Railsの起動時間を7分の1にした話
こんにちは。2021年12月にCAMPFIREに入社した小川です。
CAMPFIREではRailsを使って開発しています。わたしの入社後、いくつかRailsのパフォーマンスチューニングをする機会があったのですが、今回はそのうち、開発環境でのRailsの起動時間を約7分の1に短縮することができた事例についてご紹介したいと思います。
Railsの起動が遅い
CAMPFIREで開発をしはじめてひとつ気づいたのが、開発環境でのRailsの起動にやけに時間がかかることでした。計測してみると1分以上かかっています・・・。
$ time bundle exec rake environment
# ...
real 1m10.845s
user 0m8.075s
sys 0m2.086s
これは遅い。アプリケーションの規模はたしかに大きいのですが、それを加味しても遅すぎる印象です。
チームメンバーに尋ねてみると、しばらく前から遅くなっていたとのことでした。
起動が遅いとテストを実行したりといったローカルでの作業が億劫になり、開発生産性が下がります。調査して改善をしてみることにしました。
何をしたか
速度改善には大きく2つのステップで取り組みました。
Bumbler による大まかなボトルネックの把握
StackProf 、 rblineprof での詳細なプロファイリング
以降ではそれぞれの詳細を見ていきたいと思います。
Bumbler による大まかなボトルネックの把握
Bumbler は、Railsの起動で各Gemやinitializerの読み込みにどれくらい時間がかかっているかを計測してよしなにレポートしてくれるGemです。
使い方は非常にかんたんで bumbler コマンドを実行するだけです。すると、以下のように計測結果をレポートしてくれます。
$ bumbler
# ...
Slow requires:
112.92 ddtrace
116.69 enumerize
128.62 shoulda-matchers
138.91 activeadmin_addons
142.85 rails
# ... 計測結果を見たところ、極端に遅いGemはないようです。
もうひとつ、Bumlber はinitializerでどれくらい時間がかかっているかも計測することができます。今度はそちらを実行してみましょう。 --initializers オプションを付けて実行するだけです。
$ bumbler --initializers
# ...
Slow requires:
134.17 :load_environment_config
179.83 :set_clear_dependencies_hook
445.80 :finisher_hook
3106.27 :set_routes_reloader_hook
60070.21 ./config/initializers/rollbar.rb
60169.64 :load_config_initializersどうやらRollbarのinitializerの読み込みが時間を食っているようです。約60秒・・・。起動の遅さはほぼこれが原因とみて間違いないでしょう。これで大まかなボトルネックの箇所を特定することができました。
StackProfで具体的に遅い箇所を特定する
前節までで、起動時間のうち、Rollbarのinitializerの箇所で大きく時間がかかっていることがわかりました。続いてinitializerのうち、具体的にどこが遅いかを特定していきます。
今回はStackProfを使ってみましょう。定番のGemなので使ったことがあるかたも多いかと思います。
以下のようにしてプロファイルしたい箇所をStackProfのブロックで囲います。
StackProf.run(mode: :wall, out: 'tmp/stackprof-cpu-myapp.dump', ignore_gc: true) do
Rollbar.configure do |config|
# ...
end
endかんたんにオプションを説明すると以下となります。
mode : CPU処理時間など含めた全体での実行時間
out : プロファイル結果の出力先
ignore_gc : GCの実行を計測結果に含めるか否か
今回はCPU処理時間以外でボトルネックが発生している可能性も考慮して、wallを設定しています。また、GCは計測にあたってノイズになってしまうと考えられたのでignore_gcをtrueに設定しました。
では、Railsを起動して計測を開始します。
$ bundle exec rails cこのとき、注意しておくのがSpringの無効化です。Springを無効化しておかないと、正しく計測がなされません。以下のようにしてあらかじめSpringが動かないようにしておきましょう。
$ export DISABLE_SPRING=1参考: https://github.com/rails/spring#temporarily-disabling-spring
続いて、計測結果を出力します。先程の計測結果を stackprof コマンドで確認します。
$ bundle exec stackprof tmp/stackprof-cpu-myapp.dump
# ...
==================================
Mode: wall(1000)
Samples: 59181 (0.07% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
59102 (99.9%) 59101 (99.9%) Net::HTTP#connect
63 (0.1%) 40 (0.1%) Bootsnap::LoadPathCache::Cache#push_paths_locked
14 (0.0%) 14 (0.0%) Bootsnap::LoadPathCache::Path#latest_mtime
9 (0.0%) 9 (0.0%) #<Module:0x000000014ca8e808>.storage_to_output
15 (0.0%) 4 (0.0%) Kernel#require_with_bootsnap_lfi
3 (0.0%) 3 (0.0%) Bootsnap::LoadPathCache::Path#non_directory?
3 (0.0%) 3 (0.0%) Bootsnap::LoadPathCache::Path#expanded_path
2 (0.0%) 2 (0.0%) #<Module:0x000000014c83c910>.paths
59102 (99.9%) 1 (0.0%) #<Module:0x0000000158dd6ef0>.timeout
1 (0.0%) 1 (0.0%) <module:Backtrace>
1 (0.0%) 1 (0.0%) #<Module:0x00000001036e33a0>.notifier
10 (0.0%) 1 (0.0%) Bootsnap::CompileCache::ISeq::InstructionSequenceMixin#load_iseq
4 (0.0%) 1 (0.0%) Bootsnap::LoadPathCache::Path#stability
59181 (100.0%) 0 (0.0%) ActiveSupport::Dependencies::Loadable#load_dependency
59181 (100.0%) 0 (0.0%) Rails::Engine#load_config_initializer
59181 (100.0%) 0 (0.0%) #<Module:0x000000010d017eb8>.instrument
59181 (100.0%) 0 (0.0%) block (2 levels) in <class:Engine>
59181 (100.0%) 0 (0.0%) block in <class:Engine>
59181 (100.0%) 0 (0.0%) Rails::Initializable::Initializer#run
59181 (100.0%) 0 (0.0%) Rails::Initializable#run_initializers
59181 (100.0%) 0 (0.0%) #<Module:0x000000014cae6aa8>.tsort_each
59181 (100.0%) 0 (0.0%) #<Module:0x000000014cae6aa8>.each_strongly_connected_component
59181 (100.0%) 0 (0.0%) #<Module:0x000000014cae6aa8>.each_strongly_connected_component_from
59181 (100.0%) 0 (0.0%) Rails::Initializable::Collection#tsort_each_child
59181 (100.0%) 0 (0.0%) TSort#tsort_each
59181 (100.0%) 0 (0.0%) Rails::Application#initialize!
59181 (100.0%) 0 (0.0%) <main>
59181 (100.0%) 0 (0.0%) Kernel#require_with_bootsnap_lfi
59181 (100.0%) 0 (0.0%) Bootsnap::LoadPathCache::LoadedFeaturesIndex#register
59181 (100.0%) 0 (0.0%) Kernel#requireNet::HTTP#connect に時間がかかっていることがわかりました。 99.9% とあるので、ここの箇所が完全にボトルネックになっていますね。
59102 (99.9%) 59101 (99.9%) Net::HTTP#connect余談ですが、StackProfは出力結果を graphviz や flamegraph で出力することもできます。
以下では graphviz で出力した結果です。
$ bundle exec stackprof --graphviz tmp/stackprof-cpu-myapp.dump > tmp/stackprof.dot
$ dot -T pdf -o tmp/stackprof.pdf tmp/stackprof.dot
ボトルネックになっている箇所がどのように呼び出されているかを把握するには非常に便利です。
rblineprof で具体的に遅い箇所を特定する
前節で使った stackprof でも遅い箇所がどこなのかは特定できるのですが、少し切り口を変えてラインプロファイラーである rblineprof でもプロファイルしてみましょう(ちなみに StackProf も rblineprof も同じ tmm1さんの作です)。
rblineprof はそのままだとちょっと扱いづらいので、出力をいい感じにしてくれる rblineprof-report も使います。
StackProf の時と同じく Rollbar のinitializerの箇所をrblineprofのブロックで囲みます。
lineprofの引数に、具体的に行ごとの時間を計測したいファイル名(ないしはフィルター)を指定します。
profile = lineprof(/config\\/initializers\\/rollbar.rb/) do
Rollbar.configure do |config|
# ...
end
endRailsを起動すると、指定箇所のプロファイル結果が出力されます。
$ bundle exec rails c
# ...
[LineProf] ===============================================================
config/initializers/rollbar.rb
| 1 # frozen_string_literal: true
| 2 profile = lineprof(/config\\/initializers\\/rollbar.rb/) do
60338.6ms 1 | 3 Rollbar.configure do |config|
# ...
| 12
60006.5ms 3 | 13 config.host = Net::HTTP.get(URI.parse('...')) rescue nil
| 14 原因箇所が特定できました！Rollbarのhostを設定している箇所で Net::HTTP.get をしているのですが、ここで非常に時間がかかっていることがわかりますね。起動速度の改善にはここを直せばよさそうです。
原因と解決
端的にいえば、ローカル環境からはアクセスできないURLが設定されていたのが原因でした。
当該箇所はRollbarに結果を送信するときにIPアドレスから判別できるように、AWSのインスタンスメタデータにアクセスして、インスタンスのプライベートIPアドレスを取得していました。
ですが、AWSのインスタンスメタデータはAWSの環境内でないと当然ながらアクセスができません。そのため、開発環境での起動時は毎回 Net::HTTP がタイムアウトするまで待ちが発生していたわけです。Net::HTTP のタイムアウトはデフォルトで60秒なので、Bumblerで計測したときにかかっていた時間とも一致します。
というわけで、原因が判明したので修正しましょう。該当部分はRollbarが必要になる場合のみ有効であればよいはずです。以下のように本番とステージング環境でのみ設定するように修正しました。
if Rails.env.production? || Rails.env.staging?
config.host = Net::HTTP.get(URI.parse('...')) rescue nil
end修正ができたら次は改善効果の確認です。timeとbumblerで測定してみましょう。
$ time bundle exec rake environment
# ...
real 0m10.634s
user 0m8.067s
sys 0m1.989s$ bumbler --initializer
# ...
0 of 0 gems required
Slow requires:
109.23 :load_environment_config
125.73 :load_config_initializers
213.26 :set_clear_dependencies_hook
456.61 :finisher_hook
3159.21 :set_routes_reloader_hook起動時間が70秒 → 10秒と7分の1に改善しました！！
ローカルでのspec実行などがだいぶ快適になりますね。
補足
bumblerのユースケース
今回はbumblerでinitializerのボトルネックを見つけるかたちとなりましたが、開発環境で不要な(かつ時間のかかっている)Gemを見つけるのが一般的なユースケースになるかなと思います。
たとえばテスト関連のGemはジェネレーターの関係でdevelopmentにも入っていることが多いのですが、ジェネレーターをあまり使っていないのであれば、削除を検討したくなります。このとき、bumblerでどれくらい時間がかかっているかが分かることで削除の判断材料にすることができます。
StackProf と rblineprofの使い分け
どちらもボトルネックの特定には非常に有用なGemなのですが、特定のファイルのどこに時間がかかっているかを見るのであればrblineprofが使いやすいです。
一方、StackProfは使っているGem起因だったり、コードを掘り下げて調べるときには非常に有用です。今回のケースではinitializerのコードに原因があることが概ね分かっていたのでそこまで真価を発揮できた感じではなかったのですが、Gem内部のボトルネックなどを調査するときはとても役立ってくれるでしょう。
まとめ
以上、Railsでの起動をプロファイルツールを使って改善した事例をご紹介しました。まとめると以下のようになるかと思います。
速度改善においては、まず大まかなプロファイリングでボトルネック箇所を特定し、そこからより具体的に箇所を特定していくとやりやすい
BumblerはRailsの起動周りで大まかなボトルネック箇所のプロファイリングに便利
rblineprofはボトルネックとなるファイルが分かっている場合、使いやすい。一方、StackProfはもう少しボトルネックの発生箇所が込み入っているときに便利。
今回のような大幅な改善につながるケースは実際はあまりないかもしれませんが、ボトルネックを特定し、改善するプロセスについては参考にしていただける部分も多いのではないかなと思います。みなさまの速度改善の参考になれば幸いです。
参考資料
この記事が気に入ったらサポートをしてみませんか？