読者です 読者をやめる 読者になる 読者になる

0から始めるRailsアプリケーションの高速化改善

みんなー、げんきー?ヽ(•ㅂ•)/
最近は土日のスケジュールを事前に計画するようになったよ。

ちなみに今週土曜の計画は途中でお昼寝を挟んだことにより1/3のタスクが遅延状態になった。遅れを取り戻すべくタスクリストを粛々と消化していこう、部屋を掃除したら次はブログ記事の作成だ。

今日の話は初心者向けのパフォーマンスチューニングについて。とりあえずRailsアプリで作られた小中規模なサービス、目安としては月間100万PV行かないようなサービスを想定している。

……高速化しちゃう? しちゃおっか!

まず計測からはじめよ

f:id:oneforowl:20170318210618j:plain

これは改善全般に言えることだが、もっとも重要なのは計測だ

計測することで初めて「改善すべきである」ことを発見でき、課題が意識の前景へと浮かび上がる。課題が計測を通じて意識の中に現れると、人間は自然とそれを改善すべく動き出すのである。

例えば「体重計に毎日乗る」「摂取カロリーを計測する」それだけで食生活が改善されていく。改善とは即ち計測することだ。仮にチューニングする気がないにせよパフォーマンスの計測だけでもしてみよう。ね、計測だけ! 計測だけだから!

どこが、何に、手間取っているのか

さて、具体的な計測の方法について。まず最初に見るのは言うまでもなくRails自体の/log以下に生成されるログだ。

Started GET "/job_portal" for ::1 at 2017-03-18 21:24:26 +0900
Processing by JobController#index as HTML
(中略)
(0.3ms) SELECT COUNT(*) FROM `master_articles` WHERE `master_articles`.`service_id` = 1
Rendered layouts/_side_nav.html.slim (2.9ms)
Completed 200 OK in 50ms (Views: 44.0ms | ActiveRecord: 3.0ms)

とりあえず赤字にしている行を見てみよう。リクエストに対して必要な処理を終えるのにかかった合計時間は50ms、そしてその横にViewsとActiveRecordそれぞれで掛かった時間が記録されているのがわかるだろう。

viewsはRailsがerbやslimといったテンプレートファイルを、そこに記述されている動的な要素を埋めてhtml化する処理時間(レンダリング)、ActiveRecordはデータベースへのアクセスによる処理時間だ。

一言にページ表示で時間がかかると言っても、レンダリングとデータベースのどちらが時間をかけているのかによって対応方法が変わって来るというワケ。

前提を説明したところで、どのページが頻繁に呼び出されて、どのページが特に重いのかを調べるとしよう。対応すべきなのはアクセスが頻繁なページか、非常に表示まで時間がかかるページなのだから。

request-log-analyzer

良い知らせだ、便利なツールがある。ログファイルを解析して各ページ毎に「平均応答時間」「標準偏差」「最大最小時間」などを取得し「DBアクセス時間順」「リクエスト数順」などに並び替えて表示してくれる。それがrequest-log-analyzerというgemだ。

github.com

細かい使い方はググるなりgithubwiki見るなり。二行で使い方を説明すると

$ gem install request-log-analyzer
$ request-log-analyzer ログファイルのパス  --format rails3 --output HTML --file result.html

これでとりあえずログファイルを解析したresult.htmlが出力される。ログファイルがデカすぎて解析に尋常じゃない時間がかかるだって? オーケー、それはログローテーションのバッチを組むなり、Railsのログ設定を弄るなりしよう。

ref: Railsでログの設定+ローテートを行う - Qiita

 

f:id:oneforowl:20170318223446p:plain

無事に解析結果が表示されたかな。これを元にユーザーの時間を大きく無駄にしている箇所を見つけて優先的に対処しよう。しかし最後の更新が2年前で開発が停滞しているのがやや心配だ…。ちなみに、このgemはrailsだけでなくnginxやhttpdといったサーバーアプリからmysqldやmuninのログも解析可能なので試してみてくれ。

とにかくログを見よう

上記ではどのアクションで時間がかかったのかはわかっても、データベース上で実際に走ったSQLは確認できない。あまりに時間がかかっているのであればMySQLなどのスロークエリとして記録されているはずだ。記載されているSQLをEXPLAINするんだ。さぁ、ログファイルを確認してみよう。

Railsの処理は早いはずなのに実際にブラウザで表示するとずっと重い? Apacheやnginxなどのサーバーアプリで何か時間のかかる処理を行っているかもね。ログファイルを確認してみよう。

生ログは本番環境だと1日で軽く数十MBを超えてしまうため、閲覧の仕方がよくわからない人もいるかもしれない。unixのコマンドと仲良くすれば巨大なファイルでも比較的高速に扱うことが出来る。例えばRailsログから直近のアクセスとその処理時間を見たいならこうだ。

$ tail -10000 log/development.log | grep -E "Started|Completed" | less

development.logの末尾から10000行を取り出す => StartedかCompletedを含む行を抜き出す => 処理結果をless(ReadOnlyのviみたいなの)で開く

パイプはunixの非常に便利な機能だ、rubyのメソッドチェーンみたいにカワイイだろう?٩( 'ω' )و

データベースへのアクセスを改善する

renderについては一旦放っておこう。で、このトピックは正直に言って難しい。追求していくならば非常に高度で専門的な分野だ。だがまずは基本的なことを改善するだけでいいし、大規模サービスでなければ案外それだけでも十分だったりする。そして基本的なことなら比較的容易だ。

N+1など冗長な処理を避ける

これらの問題はプログラムの書き方を変えるだけで同じ結果をより早く得られるようになる。N+1問題などの説明は省略するが、基本的な考え方は「既にDBから受け取ったはずの情報を再度取りに行くためにSELECT文が発行される」ことを避けるということに尽きる。Railsのキャッシュ機能が上手く働いているかも確認しよう。bulletのようなgemを使うことによって全てのN+1を生まれる前に駆逐することも重要だ。

ref: Rails のキャッシュ: 概要 | Rails ガイド

インデックスの活用

最も簡単でポピュラーなRDBMSのパフォーマンス改善と言えばインデックスだ。特定のカラムにインデックスが張られている場合、そのカラムを参照するSELECT文は非常に高速化される。ただしインデックスを効果的に設定するのは初心者にはやや難しいかもしれない。

インデックスの性質やデメリットについて調べる他に、効果的に利用するためコードを修正したりする必要も出て来るだろう。非常に説明が長くなるので細かいことは専門の記事を参照してほしい。

ref: MySQLでインデックスを貼る時に読みたいページまとめ(初心者向け) - Qiita

重すぎる処理は本当に必要なのか見直す

冗長な処理を避けたのにそれでも重いって? そうか、ところでこのindexアクションでOrder.allと書いてSELECT * FROM orders;を発行する必然性は本当にあるのか?Order.limit(100)とかではダメなのか? 仮に数百万レコードあるテーブルを絞り込みなしに参照するなら、どうやっても0.01msにはならない。それはチューニングではどうしようもない話だ。

故にそれが本当に必要なデータなのかを見直さなくてはならない。見直した結果、本当にそれが必要でしかも頻繁に呼び出される、ということもあるだろう。そういった場合はメモリ上にデータを保持することで高速に機能するRedisやMemcachedの採用を検討する必要があるかもしれない。

終わりがない旅のはじまり

ある程度の改善をやり終えてしまい、それでも更に改善が必要な場合はミドルウェア層やサーバー構成に手を入れる必要が出て来る。例えばメインのデータベースはRDBMSだが特定のデータについてはKVSで管理する、参照系のクエリをレプリケートしたslaveへ流す、DBの設定をチューニングする……。

データベース以外にも速度を落とす要因はある。もしかするとDNSやサーバーアプリがパフォーマンスのボトルネックになっているのかもしれない。

こうしてパフォーマンスの追求はプログラミングの技術から上流へと行き着く。作ろうとしているのがサービスやシステムである限り、ミドルウェアやネットワークの知識を習得することは避けて通れない、備えよう。