おそ〜いRailsサービスを、はや〜いRailsサービスに改善してみた（調査編）

はじめに

「Railsで運用しているサービスが激遅なんだけどなんとかならないか？」

というご相談をいただいた。速度改善のお仕事をガッツリもらうことは少ないので、これは良い機会だと思い記録を残しておくことにした。

調査の過程を一通り記録しようと思うので少々冗長かもしれないがあしからず。

依頼内容

トップページとコンテンツページを平均3秒以内で表示されるように高速化。

改善の流れ

• 速度測定
• 原因の調査 <= 今回はここまで
• 調査結果から実際の改善案を考察
• 改善案を実行
• 結果

以上の流れで進めてみようと思う。
もちろんサーバーもフロントも両方対応する。

あと、根本問題の解決のためにフラグメントキャッシュなどのキャッシュを使うのは色々と改善した後使うことにする。

検証環境

検証環境は以下のような形。
特に断りのない限り速度の測定はローカル環境でやっている。

• PC: Mac book pro
• サーバー： dockerで起動
• Rails： Rails 5.2.0
• Ruby： Ruby 2.5.1
• テンプレート: haml
• フロント: webpack, vue.js

速度測定

まずはRailsのコンソールに出力されるログを見てみる。
Railsで各ページにアクセスした時に最後に出力されるアレだ。

以下が対象サービスのトップページを読み込んだ時のもの。

Completed 200 OK in 4963ms (Views: 4733.4ms | ActiveRecord: 72.7ms)

遅すぎねぇかこれ。。

何かの見間違いかしれないので何度か試したが誤差は少しあるものの結果はほぼ変わらなかった。Rails側でこんだけ遅いので最終的に表示される速度はもっと遅そう。

さっそく、実際にページを読み込んだ時の速度をChromeのデバッグツールで計測。

Finish 12:40s !!!

あくまでもlocal環境なのでキャッシュが効くproduction環境であればもう少し早いがこれは遅い。

次にPageSpeed Insightsを使ってみる。
ちなみにWebからアクセスする関係上こちらはproduction環境のもの。
https://developers.google.com/speed/pagespeed/insights

うわぁ。production環境なのに見事に最低評価です。

ということで、これは非常に改善しがいがあるなぁ(白目)。

原因の調査

現状確認

早速原因調査というところで、まずは白紙ページを作成して現状環境で最高速度を計測しておく。

とりあえず以下のような空状態のコントローラーを用意。
テンプレートには何も記述しないものを使用した。

class SpeedsController < ApplicationController

  def show 
  end
  
end

表示結果は当たり前だが空白。
ただし application.html.haml はそのまま使っているのでjsやcssは読み込まれている。

この状態の計測結果がこちら。

Completed 200 OK in 632ms (Views: 581.6ms | ActiveRecord: 3.0ms)

ふむ。一応 8分の１ぐらいにはなったか。
さらに application.html.haml にある共通部分も削りきってみる。とりあえず削りまくって以下のようになった。

%html
  %head

  %body

    = yield

表示結果は真っ白なので割愛。
そして計測結果。

Completed 200 OK in 109ms (Views: 45.0ms | ActiveRecord: 4.1ms)

さらに 6分の１ぐらいまで速度改善された模様。

削りに削ったので当たり前の結果だが、一旦この数値を理想値として原因を探っていくことにする。

共通処理を調査

上記の調査結果からするとActiveRecordよりもViewsの部分でかなり遅くなっている。さらに、全てのページで使われる application.html.haml の処理だけで 581.6ms かかっているのでまずはここを遅くしている原因を調査する。

とりあえず render(パーシャル) で部分テンプレートを８つほど呼んでいるのでこの辺が怪しいとみて部分テンプレート部分だけ削ってみる。具体的には以下のような記述部分を全部削って再度速度を見てみる。

  = render 'application/hogehoge'

計測結果

前 -> Completed 200 OK in 632ms (Views: 581.6ms | ActiveRecord: 3.0ms)
後 -> Completed 200 OK in 301ms (Views: 243.3ms | ActiveRecord: 1.8ms)

倍ぐらい早くなっとる。
ということで以下の施策を仮実施

• 共通化できる部分テンプレートは共通化
• 部分テンプレートにする必要がないものはインラインに書く

結果 部分テンプレートは８箇所から２箇所へ削減。
そして計測結果。

施策前 -> Completed 200 OK in 632ms (Views: 581.6ms | ActiveRecord: 3.0ms)
施策後 -> Completed 200 OK in 321ms (Views: 275.2ms | ActiveRecord: 1.8ms)

処理速度をほぼ半分にすることに成功。 やったね！

やはりRailsの部分テンプレートは使えば使うほど遅い模様。

次になんとかなりそうなのは css jsの読み込み周り。
jsの読み込みをみてみるとヘッダーだけで、５箇所読み込んでる場所がある。
ちょっと多いんじゃないかなこれ。

これもまた全部外してみる。

外す前 -> Completed 200 OK in 321ms (Views: 275.2ms | ActiveRecord: 1.8ms)
外した後 -> Completed 200 OK in 213ms (Views: 161.9ms | ActiveRecord: 2.8ms)

平均して100msほど早くなった。
ただ、ここはサクッと共通化とは行かなそうだったので後で改善策を考えることにする。

あとは ActiveRecord側だが同じSQLを２回実行している処理が１つあったのでそこだけ修正しておいたが、変化は1msぐらいだった。

トップページの調査

サーバーサイド(ほとんどViews)

さてこの辺で共通部分のボトルネックは概ね調査できたので、今回の最大のテーマであるトップページの調査にうつる。

まずお決まりの測定から。

Completed 200 OK in 4473ms (Views: 4326.4ms | ActiveRecord: 42.4ms)

あああぁ！おっそい！

先ほど共通部分を改善したので少し数値は良くなったものの、依然として叫びたくなるぐらい遅い。

改善せねば、改善せねば。

ということで、4326.4msもかかってるView周りを調査する。

とりあえずページアクセスをする時にRailsコンソールに表示される情報を見てみると。HTMLのRender周りで以下のログが出ていた。

Rendered partials/hogehoge.html.haml (4754.8ms)

うぉ！　いきなり元凶っぽいの見つけた。っていうかこのテンプレート遅すぎ。。
他にも 100msとか300ms超えてるテンプレがゴロゴロある。やばい。

とりあえず上記のテンプレートを呼び出す処理を削除してみる。

削除前 -> Completed 200 OK in 4473ms (Views: 4326.4ms | ActiveRecord: 42.4ms)
削除後 -> Completed 200 OK in 845ms (Views: 709.3ms | ActiveRecord: 19.0ms)

そうですよねー。元に比べれば、めっちゃ早くなった。
さて、消したままでもいられないので肝心の中身を確認する。

実際のコードとは違うが概ね以下のようなコードが書かれていた。

- hoge.each do |hoge|
  = render 'partials/hogehoge1', :col => hoge,
  = render 'partials/hogehoge2', :col => hoge,
  = render 'partials/hogehoge3', :col => hoge,
  = render 'partials/hogehoge4', :col => hoge,

うわぁ。こりゃ遅くもなるわ。

hogeの要素数x4も部分テンプレートを呼び出してるわけだから１０件データがあるだけで４０回も部分テンプレートを呼び出すことになる。

ちなみに部分テンプレート呼び出しが多いと処理が重くなる理由については下記の記事が詳しいので読んでみると参考になる。
https://qiita.com/itmammoth/items/612efc6ad3280349b7e1

さて、ここでも無駄な部分テンプレートを一生懸命削ってみる。

早速、ある部分テンプレートを削ったところ

削る前 -> Rendered partials/hogehoge.html.haml (4754.8ms)
削った後 -> Rendered partials/hogehoge.html.haml (2694.5ms)

1000msぐらい早くなった。気になって中身をみるとそのテンプレートの中にもさらに部分テンプレートが４つあった。。

要素数x4x4!!
少し無理やりだが以下のようなコードを書いてるに等しい。

- hoge.each do |hoge|
  = render 'partials/hogehoge1'
  = render 'partials/hogehoge2'
  = render 'partials/hogehoge3'
  = render 'partials/hogehoge4'

  = render 'partials/hogehoge1'
  = render 'partials/hogehoge2'
  = render 'partials/hogehoge3'
  = render 'partials/hogehoge4'

  = render 'partials/hogehoge1'
  = render 'partials/hogehoge2'
  = render 'partials/hogehoge3'
  = render 'partials/hogehoge4'

  = render 'partials/hogehoge1'
  = render 'partials/hogehoge2'
  = render 'partials/hogehoge3'
  = render 'partials/hogehoge4'

１０件データがある場合 160回も renderを呼び出すことになる。
正気の沙汰じゃねえ。

と震えてたら残りの部分テンプレートにも3つ部分テンプレートを呼んでるやつがいた。。
と思ったらさらにその中でも部分テンプレートが３つ。
なんとさらにその下に部分テンプレートを２つ呼んでるやつがいた。

要するに
要素数x((4x8)+(4x4))

１０件データがある場合 480回も 部分テンプレートを呼び出している。

結局、他の部分テンプレートも似たようなものだったので、最終的に１０件データを表示するのに700回ぐらい部分テンプレート呼んでるんじゃなかろうか。そりゃ遅いわ。。

さて、依頼元に聞いたところ、このテンプレートについてはそもそもvue.jsで非同期化しようという話らしいので一旦外した状態で調査を続行することにする。

残しとくと気分的にも早くなった気がしないし。
ということで現在の速度を測定。

Completed 200 OK in 896ms (Views: 732.4ms | ActiveRecord: 27.3ms)

激遅テンプレートを丸々削ったのでまあ妥当な速度。

ここからさらに怪しいテンプレートを探ってみたが、部分テンプレートが複数使われていたりテンプレートに過剰にロジックが書かれてる場所が遅くなっているようだ。

ロジックに関してはテンプレートにif分岐が大量に書かれていてしかもほとんどがサーバーサイドに寄せれる内容だったので一旦全部消してしまった。

テンプレートにロジック書きまくるの止めよう!！

さて、問題の箇所を修正した結果が以下。

Completed 200 OK in 509ms (Views: 401.6ms | ActiveRecord: 14.9ms)

だいぶ理想の速度に近づいてきた。

ここで消した要素に使っていたサーバーサイド側の処理も削除。

Completed 200 OK in 470ms (Views: 399.0ms | ActiveRecord: 6.0ms)

少しだが早くなった。

この辺で一回 Chromeのデバッグツールでも描写速度を計測してみる。

こちらが改善前。

こちらが改善後

おお、とうとう3秒切った！
ちなみに、削った要素の中に画像なども含まれていたのでその分余計に早くなったというのもある。

フロントの調査

サーバーサイド（といってもほとんどView）は割と早くなったのでそろそろフロント側の調査を進めようと思う。
一から調べるのも良いが、ここは以前計測したPageSpeed Insightsに改善策の提示があったのでそちらを見てみることにする。

画像についての指摘が多い。ということで画像周りから調査してみる。

Chromeのデベロッパーツールで調べると明らかに重いのが１つあった。

でかい、しかもpng画像である必要が全くなさそう。
ということでjpgに変換することにする。

いいね!

似たような画像がもう一つあったのでそれもjpgに修正して再度計測してみる。

すごく微妙な変化だがtransferredが3MBほど減少している。
画像に関してはこれ以上あまり改善が見られなかった。

次に項目の４番目にある「レンダリングを妨げるリソースの除外」あたりをみてみる。
内容としてはcssやjsの読み込み時にレンダリングがブロックされるため延滞が発生している模様。

Chromeのデベロッパーツールだとこの辺だと思われる。

んー　それぞれのファイルの読み込みが遅いのもちょっと気になるが、とりあえずPageSpeed Insightsの指示に従ってjavascriptがレンダリングを妨害しないようにdefer属性をつけてみる。もちろんjsエラーが出ないように修正。

おー、微妙に速度アップ。Finishが1秒台ももうすぐ達成できそうか。

さて、上の測定後に色々と調べたがこれ以上はjavascriptとかcssをリファクタしないと速度改善はできなさそうだった。一応フラグメントキャッシュも使ってみたが、遅くなっているのが以下のようなjsやcssの読込み部分らしくトップページに関してはほとんど効果が得られなかった。

= stylesheet_link_tag 'application', media: 'all'
= javascript_pack_tag  'application', defer: true
= javascript_pack_tag  controller.controller_name, defer: true

ちなみに上記を外した時の測定結果。

とうとう1秒を切った！

だが、コードを消しただけなのであまり意味はない。現状だとjsファイル１つで1MB以上あるっぽいのでここを削減するのが良さそう。

もちろん上記と同じ速度にはならないだろうが1秒台ぐらいにできるように調整したいところだ。

コンテンツページの調査

次にコンテンツページの調査に入る。
トップページと似たような問題だと思うので同じような手順で調べてみる。

最初にページ表示時のRailsのコンソールを見てみる。

Completed 200 OK in 4318ms (Views: 3542.2ms | ActiveRecord: 284.2ms)

予想通りViews周りがひどい。ただ、今回はActiveRecordもそこそこ遅い。
とりあえずViewから調査。

Rendered partials/_hoge.html.haml (582.6ms)
Rendered partials/_hoge_hoge.html.haml (545.3ms)

名前は変えてあるがこの２つのファイルがいずれも500ms超えている。
そして中身を見てみるが。。

あぁ　トップページと一緒だわ。

案の定というか部分テンプレートが５つありそれをeachしている。もう一方のテンプレートも同じ。
とりあえずここを削ってみる。

Completed 200 OK in 1485ms (Views: 1004.9ms | ActiveRecord: 105.8ms)

当然のごとく倍近く高速化。それでもだいぶ遅い。。
この辺から、パターンがトップページと一緒なので無駄だったり遅くなっている要素を削り切った結果だけ以下に記載しておく。

Completed 200 OK in 636ms (Views: 486.0ms | ActiveRecord: 26.5ms)

ActiveRecordもだいぶ早くなっているが、これは遅くなっている要素を削ってSQLの発行がかなり減ったため。

一応ページの表示時の速度も載せておく。

コンテンツページは以上！

原因がトップページと同じく部分テンプレートの乱用だったのであまり面白みのある調査内容ではなかった。

何となくだが、このサービスの傾向として多機能というのがあって、あれも付けたい、これも付けたいという開発者側の意図が感じられた。ただ、その時にパフォーマンスについてはあまり考慮に入ってなかったようだ。

いくら多機能でもページがこうも遅いとほとんど使い物にならないので最初からパフォーマンスも考慮に入れて開発するのが良いと勝手に思った次第。

とりあえず調査終了 - そしてまとめ

今回判明した延滞の原因

• 部分テンプレート(パーシャル)使いすぎ
• テンプレート側で分岐処理などのロジック書きすぎ
• javascriptやcssなどの読み込みファイルが多い、あと容量も１つ1MBほどある

調査開始時はN+1問題とか、スロークエリがめっちゃ発行されてるとかを想定していたのだが、蓋を開けてみるとほぼテンプレート側の問題だった。まあ、テンプレートに書いたコードによってSQLが発行されちゃうので無駄なクエリの発行も結構あったのだが。個人的には、もっとコントローラーやモデル周りの問題だと思っていた。

Railsの部分テンプレートは乱用するとめちゃくちゃパフォーマンスが悪化するというのは個人的にも勉強になった。

次回

さて、今回は調査だけだったので遅いコードをとりあえず消す！みたいな対応で済ませた。次は実際にどう修正すべきかの改善策を考えて実行できればと思う。