Railsのパフォーマンスチューニングしたらトップページの速度が100倍になった。
皆さん、こんにちは。
見習いエンジニアのkey(id:key_libres)です。
Twitterもやっているのでぜひフォローして下さい→@key___sn
先日、PRESSブログにおける未ログイン時のトップページをリニューアル致しまして、その際レスポンスが異常に遅かったり、サーバーへの負荷が大変なことになり、なんどもサーバーが落ちてしまいました。
その後、開発メンバーの統括をしているsainu(@sainu_____)に協力してもらい、原因を調査・対策することで結果としてサーバーへの負荷が軽くなり、Railsを高速化することが出来ました。
結論としては、
- インデックス
- キャッシュ
をしっかり使いこなしましょうというお話です。
ことのはじまり
早朝のデプロイが完了後、
ものすごい大量にアラートが来るようになりました。
このアラートは、下記の画像のようにロードバランサーとターゲットの応答時間が300ms以上かかっている時にきています。
調べてみると、トップページや検索ページの処理時間が異常に長いことがわかり、
特に今回リニューアルしたトップページのx-runtime(サーバーでの処理時間)に4sほどがかかっていました。
原因調査・対策
スロークエリ対策(index)
本番のログを確認すると、
D, [2018-05-14T07:50:09.852137 #9615] DEBUG -- : (4009.6ms) SELECT ・・・
ものすごい大きなクエリが出ていました。
EC2のモニタリングを見るとCPUやメモリの空き容量に問題がなく、RDSのリソースを確認してみるとCPUが100%になっていたので、ひとまずスロークエリを解決することから始めました。
ローカルで確認したところ、どうやら記事テーブルを投稿順にソートする
scope :latest, ->{order(published_at: :desc)}
で遅くなっていることが判明しました。
ActiveRecordのorderメソッドでは全レコードを処理するので、記事テーブルのようなレコード数の多いテーブルではものすごい処理時間がかかっていました。
そこで、投稿順にソートするロジックはよく利用するので、ソートしたテーブルに対してインデックスを貼ることにしました。
新しくマイグレーションファイルを用意して、
add_index :articles, :published_at, order: { published_at: :desc }
を追加してrake db:migrateしました。
- インデックスを貼る前
- インデックスを貼った後
ものすごく早くなりました。
他にも少し重いクエリはあったのですが一旦、こちらでデプロイして、様子を確認しました。
トップページのトランザクションが減りましたね。
しかし、最もアクセスが増える夜の時間帯にて502(Bad Gateway)が返ってくるようになりました。
ビューキャッシュによる先行評価対策
Google Analyticsは通常通りなのですが、サーバーの状態がおかしかったのでLoad Averageを確認すると、
load average: 5.67, 2.58, 1.91
やばいですね。。
他のサーバーも
load average: 2.11, 6.08, 6.32
となっています。
Load Averageは
「1CPUにおける単位時間あたりの実行待ちとディスクI/O待ちのプロセスの数の合計」
で表され、各サーバーのCPU数は1つなので1.00を超えるとサーバーの負荷としては大きいということなのですが、大幅なオーバーをしています。
このような時は、
- 異常なプロセスがないか確認←大体unicorn
- nginxの再起動
- unicornの再起動
- メモリやCPUをチェック
あとは、
- ロードバランサのバランス機能の確認(load averageにばらつきがあるので)
- データベースに対するCPUの確認
などの対策が考えられます。
今回、データベースに対するCPUを確認すると
CPUの利用率の上昇に伴い、
読み書きも急激に上がっているので、重いクエリが走っているようなことが予測されました。
そこで、slow_log.sqlを確認すると
$ tail -r slow_log.sql | grep “TopController,action:index,line:/app/controllers/top_controller.rb:38” | wc
4万件近く上記に関連したslow logがありました。 該当箇所では、
@hoge = User.joins(:fuga) ... .uniq.limit(5)
のようにuniqを使っていたので、ビュー側でこのインスタンス変数をフラグメントキャッシュをしていても、コントローラー側でrubyの関数uniqによる値の評価が必要なので、毎回クエリが発行されていました。
PRESSブログでは、1日でリアルタイム2000人以上、PVが60万ほどになることもあり、トップページの全ページの中でもトップ10に入るくらい多くのアクセスがあるページなので、毎回クエリが発行されるととんでもない負荷がサーバーにかかっていました。
そこで、一時的に ビューのフラグメントキャッシュ内に先行評価されるロジックを入れることにより、キャッシュされている間はクエリが発行されないようにしました。
注) 本来は、キャッシュ部分のクエリが出ないようにコントローラーのロジックを書き直すか、ビューキャッシュではなくモデルを作成してDBに保存しておくのが良いです。緊急対応として一旦、こちらの方法を採用しました。
これにより、さらなる高速化を実現することができました。
これでデプロイをしました。
しかし、circle ciを用いてデプロイが完了しても本番で早くなっていませんでした。
デプロイの反映
デプロイ完了後に、本番のログを確認するとローカルでキャッシュされたクエリがキャッシュされておらず、デプロイ前と変わらないログが出ていました。
したがって、デプロイが上手く行われていないことが予想され
$ cat REVISION
を実行するとrevisionが本番と同じ環境にしているステージング環境と一致していたのでunicornが原因だと考えられ、unicornを一旦killして、起動し直しました。
再起動は、設定でkillコマンドに-s USR2オプションをつけており、処理中の大きなプロセスが終了するまでデプロイが反映されないため、killしました。
結果、
かなり早くなりました。
Webサービスは基本的にx-runtimeが0.1s以下でないとユーザーはストレスを感じてしまいますので、これからも0.1s以下を保てるようにしていきます。
最後に
今回の問題はたくさんのユーザーがいて、PVのあるサービスでないと起きない問題です。
ただ仕様通りのページが表示されるようにプログラミングするだけでなく、テーブルの構造やページのリクエスト数などを考慮して、適切にキャッシュやインデックスを貼り、サーバーの負荷を軽減するようなプログラムにすることも大事だということを学びました。
今回の反省を活かして、より良いサービス開発を頑張ります！
