rack-mini-profiler RubyとRailsの実行速度を改善するための秘密兵器
SpeedShop(詳細),Railsパフォーマンス・コンサルタンシー
ネイト・ベルコペック Nate Berkopec (@nateberkopec)
要約:rack-mini-profilerは、Rackアプリケーション用の、スイス・アーミーナイフのようにパワフルなパフォーマンス・ツールです。SQLクエリ、メモリの使用状況、 CPUの消費時間を計測します。
rack-mini-profilerはRackアプリケーション用のパフォーマンス・ツールです。優秀な開発者の サム・サフラン@samsaffronが管理しています。ここに(rack-mini-profiler)Rackによって作成されたwebアプリケーションのパフォーマンスを計測するための、総合的なツール・スイートが提供されています。SQLクエリ、Rubyのテンプレートやパーシャルごとの応答時間を計測できます。フレーム・グラフ(flamegraph)の素晴らしい機能によって、実行時間の内訳が、ミリ秒単位で驚くほど詳細に表示されます。優れたガベージ・コレクション機能は、メモリ・リークの追跡に役立つでしょう。rack-mini-profilerは私の好きなツールで、高速なRubyウェブ・アプリケーション開発のために最も重要なツールだと断言できます。
rack-mini-profilerの最も良い点は、製品モードで動作するように設計されていることです。そうです！rack-mini-profilerで製品のパフォーマンス(言うなれば開発モードの3倍は早い)を正確に計測することができるのです。もちろん開発モードでも動作します。しかし通常、開発モードの環境は、製品モードと異なる点が多くあります。ハードウェアやビジュアリゼーション、システムの設定は全て異なりますが、これらはパフォーマンスの大きな部分を占めています。言うまでもなくRailの開発モードの環境は、リクエストのたびにクラスをリロードするようなしろものです！
この記事では、rack-mini-profilerについて深い部分まで触れ、Railsアプリケーションのパフォーマンスを最大化するための、強力な各機能を説明します。
インストール
ここではRailsアプリケーションの開発を想定して説明しています。純粋なRackアプリケーションの場合、インストール手順は少し異なります。詳しくはREADMEを見てください。
まず、gemファイルを開いて、‘pg’や‘mysql2’などデータベース関連のgemの下に、次のgemを追加しましょう。
gem 'pg' # etc etc
gem 'rack-mini-profiler'
gem 'flamegraph'
gem 'stackprof' # ruby 2.1+ only
gem 'memory_profiler'
rack-mini-profiler はよいとして、他のgemは何をするのでしょうか？
flamegraph はとても洗練されたフレーム・グラフを提供します。後でこの記事の中で紹介します。
stackprof はスタック・プロファイラーのようなものです。フレーム・グラフを作成する際に重要なものです。このgemはRuby2.1以降のみ対応しています。そうでなければ入れないでください。(rack-mini-profilerは他のgem、fast_stackに自動的に置き換わります。)
memory_profilerはrack-mini-profilerのGC(ガベージ・コレクション) 機能を使用可能にします。
サーバを開発モードで起動して、ページを表示してください。左上にスピード・バッジが新しく表示されるはずです。これが何をするのかは後で説明するので、すぐわかります。
rack-mini-profilerの機能一覧と、起動方法を知るには、?pp=helpをURLの後に追加してください(*3)。使用可能なコマンド一覧がヘルプ画面に表示されます。(すべてのコマンドはURLクエリ文字列として追加することで使用できます。)
*3 rack-mini-profilerの最新バージョンでは、コマンドに加え、‘help’ボタンがスピード・バッジ上にあります。
オプションは全て後ほど説明しますが、まずは製品モードに設定されたローカル・マシン上で、アプリケーションを起動する必要があります。
rack-mini-profilerは製品モードで動作するように設計されています。製品モードのRailsの環境では、開発モードと比較すると、アプリケーションは大分違った動作をするでしょう。実はほとんどの場合、Railsアプリケーションは、開発モードでは製品モードと比較して、5〜10倍遅いのです。リクエストのたびにアセットの再コンパイルと、コードの再読み込みが起こるためです。そのため、実行速度の計測をするには、ローカルで確認するだけだったとしても、サーバーを製品モードで実行しなければなりません。もちろん注意が必要です。実際の製品用のデータベースをアクセスしないように、database.ymlファイルを変更して下さい。(HEROKUを使ってデプロイしているアプリケーションの場合は必要ありません。)
rack-mini-profilerはデフォルトでは開発モードで動作します。製品モードで使用できるようにして、URLパラメータの背後に隠蔽してしまいましょう。adminユーザーの時だけ、見えるようにすることなどもできます。
# in your application_controller
before_filter :check_rack_mini_profiler
def check_rack_mini_profiler
# for example - if current_user.admin?
if params[:rmp]
Rack::MiniProfiler.authorize_request
end
end
また、rack-mini-profilerのストレージのデフォルト設定を使用しないことをお勧めします。デフォルトでは、データを保存するために、ファイル・システムを使用します。この設定でとりかかると遅くなり、HEROKUを使用している場合は特に遅くなります。(本物のファイル・システムを使用しているわけではないため。)
# in an initializer
Rack::MiniProfiler.config.storage = Rack::MiniProfiler::MemoryStore
もしSSLを使った開発にフォーカスしている場合、設定をしばらくOFFにしたくなるでしょう。
config.force_ssl = false
最後に、アプリケーションを製品モードで動作させる必要があります(*4)。ここでは、(Rails4.2アプリケーションの場合)製品モードのデータベースのセット・アップ・タスクを実行する必要があるだけです。アセットをコンパイルして、SECRET_KEY_BASEをRailsのサーバ・コマンドに追加します。
*4 もし製品モードでスピード・バッジが表示されないトラブルがある場合、Rack::Deflateか、他のgzip圧縮ミドルウェアが使用されています。この場合他にも設定が必要です。rack-mini-profilerがgzipのレスポンスにHTMLを追加しようとしていないことを確認する必要があります。
RAILS_ENV=production rake db:reset # CAREFUL!
RAILS_ENV=production rake assets:precompile
RAILS_ENV=production SECRET_KEY_BASE=test rails s
スピード・バッジ
さあ、スピード・バッジを説明するときがきました。開発モードに設定されたRailsサーバーを起動し、ルートURLを表示すると、この記事で使用するアプリケーション例では、2つのスピード・バッジが作成されます。rack-mini-profilerはアプリケーションのリクエストごとに、スピード・バッジを作成します。アセット・リクエストも含みます。ここではファビコン(favicon)のリクエストにも、スピード・バッジが作成されています。
スピード・バッジをクリックすると、ページを表示するのにどのくらいのレンダリング時間がかかったか、テンプレートごとに、rack-mini-profilerが細部まで解析し、レイアウトごとに分割します。例えば、パーシャルごとのレンダリング時間に分割されます。下は、私が開発している、アプリケーションでの例です。
この表示はとても分かりやすいと思います。正にそれぞれのリクエストにかかった時間が、短い概要からわかります。表示されている、どのリクエストについても、以下のことに注意してください。
■SQLクエリをいくつ作成しているか？
このビューでは、合計9つのSQLクエリを作成しています。特に今回のような、ログイン・ユーザーのためのホーム・ページではない場合は大問題です。通常シンプルなページでは、1〜3回以上のクエリーは見たくないでしょう。ほとんどの場合、いつもActive Recordモデル・クラスごとのoneJavクエリだけにしたいはずです。
■リクエスト時間の合計がいくつか？
85ミリ秒と少し遅いです。このような、ほぼ固定でアクセス数が多いページでは、(前に言った通り、これはホームページです)50ミリ秒以下での終了が望ましいです。
■SQLに費やされた時間は何％か？
SQLの処理時間としては良好です。私はいつも製品用のデータベースのコピーを使って、アプリケーションをテストしています。できるだけクエリの計測結果が製品での結果と一致するようにしています。開発用のシンプルなデータ・ベースが1000結果を返す時間で、製品用のデータベースは100,000の結果を返せる、ということはよくあります。
■DOMContentLoadedが発効されるのにどのくらい時間がかかっているか？
レスポンスを受け取ってから、全てのコンテンツをロードするまで、約250ミリ秒かかっています。今回のようなシンプルなページではよい結果です。この時間を減らすには、フロント・エンドの最適化が必要です。記事では触れませんが、例えばイベント・ハンドラやフロント・エンドのJavaスクリプトを減らしたり、外部リソースをページに読み込む順番を調整したりします。
■他の部分と比べて、ページ中に目立って時間を消費している場所はないか？
ただ一つのパーシャルが、ページのロード時間の大半を占めているといった状況が時々あります。もうしそうなら、何が起こっているか知るために、もっと調べなければならない箇所になります。このケースでは、ページのロード時間は均等によく分散されていますが、ポスト・パーシャルがいくつかSQLクエリを作成しているようです。キャッシュの使用が主な対応策になります。(もしくは単に、最初のページでクエリーをするのを避けるか。)
他にもスピード・バッジにはいくつか機能があります。どのSQLリンクでもいいので、クリックしてみてください、実際に実行されたクエリの内容がわかります。下に例として２つあげます。
左上の数字(39.20ミリ秒)はこのパーシャルから次の処理までにかかった、レンダリング時間の合計です。右側の数字と少し違うことに注意してください。これはパーシャルのレンダリングにかかった実際の時間です。(16.75ミリ秒)このように「失われた時間」があるときは、フレーム・グラフ・ツールを使って調べると、どの場所に時間が使われたか正確に知ることができます。次のセクションで説明します。
rack-mini-profilerがクエリを発行したページ中の実際の行を表示することに着目してください
これらのクエリーは、おそらくビューがcurrent_user(もしくは他のユーザ)をルック・アップしていて、それがcurrent_user has_one Profileなのでしょう。
■クエリーを除去する方法を見つけるか、結果をビュー中にキャッシュします。
■includesコールを元のクエリに追加して、プロファイルと一緒に読み込まれるようにします。クエリの回数が一つ減ります。
以上の手順をページのクエリにそれぞれ適用します。クエリを削除、もしくはキャッシュできるかどうかは、私が書いた、Railでのキャシュについての詳しいガイドを参照してください。
フレーム・グラフ
この機能は、rack-mini-profiler中で、私が一番気に入っているものの一つです。知る限りでは、他のツールにこの機能はありません。今までの手順と同様に、URLクエリ文字列に？pp = flamegraphを追加すると、概要でも説明した、素晴らしいフレーム・グラフを取得できます。
「フレーム」の高さは、スタックの深さを示しています。Y軸がスタックの深さでX軸は時間です。マウスのスクロール・ホイールで、ズームイン/ズームアウトすることができます。
ページの下部に、それぞれのカラーが何を参照しているか、説明が表示されます。各々に表示されているパーセンテージは、スタック・フレーム内でのリクエストに使われた、時間のパーセンテージです。例えば、今回のSomeAppというアプリケーションでは、76.42%がアプリケーション内で使われています。残りの時間はRackミドルウェア(例えばlograge, airbrake、hirefire-resourceなど)が使いました。
説明を見ながら、フレーム・グラフをつつき回してみると面白いことがわかります。うわ、全てのスタック・フレーム中、Paperclipが28.3%も現れました！このページについてはPaperclipの呼び出しを避ける方法を探したほうがよさそうです。Paperclip::AttachmentのURL作成にほとんどの時間が使われているようです。キャッシュする方法を試したり、もしくは値を再計算しないようにすることができるでしょう。
ＧＣプロファイリング
他のツールには見られないrack-mini-profileの素晴らしい機能をもう一つ説明します。メモリの問題を製品モードでリアルタイムにデバッグできるツール・セットです。さらなる利点として、rack-mini-profilerを有効にしなければ、リクエストのパフォーマンスを損なうことはありません！
profile-gc
URLクエリ文字列にpp=profile-gcを追加して、何が起こるか見てみましょう。(通常、出力は膨大なので、生成するのにしばらく時間がかかります）
Overview
------------------------------------
Initial state: object count - 331594 , memory allocated outside heap (bytes) 75806422
GC Stats: count : 39, heap_allocated_pages : 1792, heap_sorted_length : 2124, heap_allocatable_pages : 353, heap_available_slots : 730429, heap_live_slots : 386538, heap_free_slots : 343891, heap_final_slots : 0, heap_marked_slots : 386536, heap_swept_slots : 343899, heap_eden_pages : 1439, heap_tomb_pages : 353, total_allocated_pages : 1852, total_freed_pages : 60, total_allocated_objects : 4219050, total_freed_objects : 3832512, malloc_increase_bytes : 960, malloc_increase_bytes_limit : 26868266, minor_gc_count : 27, major_gc_count : 12, remembered_wb_unprotected_objects : 9779, remembered_wb_unprotected_objects_limit : 19558, old_objects : 366156, old_objects_limit : 732312, oldmalloc_increase_bytes : 1344, oldmalloc_increase_bytes_limit : 22319354
New bytes allocated outside of Ruby heaps: 1909904
New objects: 17029
最初のセクションです。出力に見覚えがあるでしょうか、そうです、これはGC.statの出力です。 GCはstdlibのモジュールで、ガベージ・コレクタを扱うための便利なメソッドがたくさんあります。 statは上記の出力を返します。 各値の意味についての詳細な説明は、サム(Sam)の記事、RubyのGCはどのように機能するかを読んでください。
一番下には、Rubyヒープの外部に割り当てられた新しいバイト数が、オブジェクト数と一緒に表示されます。 異常に高い値を生成するリクエストには、全て注意を払ってください。(例えばリクエストのたびに、10Mバイト以上割り当てられる場合など)
次のセクションです:
ObjectSpace delta caused by request:
--------------------------------------------
String : 9285
Array : 3641
Hash : 1421
Regexp : 375
MatchData : 349
RubyVM::Env : 214
Proc : 204
Time : 173
Psych::Nodes::Scalar : 168
...このセクションは、リクエストによって発生したObjectSpace内のオブジェクト総数の変化（デルタといいます）を示します。 例えば、リクエストの後に、以前より9285多い文字列があります。
ObjectSpaceは非常に強力なモジュールです。例えば、ObjectSpace.each_objectを使用すると、Ruby VM内に現在割り当てられている、全てのオブジェクトをイテレートすることができます。すごいでしょう！
このセクションはそれほど有用ではないと思いますが、莫大な数のアプリケーション固有のオブジェクト（例えば、2,000個のPaperclip :: Attachmentsなどがあげられます）は危険信号でしょう。
ObjectSpace stats:
-----------------
String : 175071
Array : 49440
RubyVM::InstructionSequence : 32724
ActiveSupport::Multibyte::Unicode::Codepoint : 27269
Hash : 12748
RubyVM::Env : 8102
Proc : 7806
MIME::Types::Container : 3816
Class : 3371
Regexp : 2739
MIME::Type : 1907
...これは、VM内に存在するクラス別のオブジェクトの総数です。このアプリケーションにとって、考慮されるべき、かなり興味深いものです。この表示にある全てのMIME::TypesとMIME::Types::Containerオブジェクトはいったいどこから来ているのでしょうか？Paperclipと関係あるのではないかと思いますが、一方で、ほとんどのgemはMIMEタイプを多かれ少なかれ使用します。実際のところ、これは悪名高いメモリ食いです。最近リチャード・シュニーマン(Richard Schneeman)はわずか１箇所の変更で、50,000オブジェクトの生成を節約しました！
String stats:
------------
444 :
352 : :
218 : /
129 : :s3_path_url
117 :
116 :
108 : a
106 : href
96 : <<
78 : [&"'><]
78 : index
73 : # Amazon S3 Credentials
...出力の最後の部分です。ある文字列にメモリが割り当てられた回数の集計です。例えば、文字列「index」は78回割り当てられています。
この出力は、どの文字列を取り出して、定数化してfreezeするか決める役に立ちます。これが、Rackが“chunked”という文字列に対して行っていることです。
なぜこのようなことをするのでしょうか？例えばRackが一つのリクエスト内で、“chunked”という文字列を1000回メモリに割り当てようとしたとすると、定数を参照するようにするだけで、割り当ては１回に減らすことができるのです。実際に、この変更が行われたのは、まさにそういった理由です。
メモリ関連の事柄で頭がごちゃごちゃになってしまったとしても、心配には及びません。 ジョン・クリベッチ(John Crepezzi)のメモリに関しての講演を見ることをお勧めします。 メモリがどのようにRubyで動作しているかについての入門です。
profile-gc-ruby-head
パラメータprofile-gc-ruby-head(*5)は洗練されたmemory_profiler gem (コードの他のベンチマークにも単独で使用できます)を使います。これは初期のprofile-gcからの派生バージョンのようなものです。リクエスト中どの文字列にメモリが割り当てられたかだけではなく、コードのどの行で実際に文字列に割り当てられたかを知ることができます。極めてパワフルな機能です。
*5 将来のリリースではこの機能の名前はprofile-memoryに変わります。
いくつかの出力例です。
Total allocated 16986
Total retained 1208
allocated memory by gem
-----------------------------------
769864 paperclip-4.3.0
382958 activesupport-4.2.3
324621 actionpack-4.2.3
274792 activerecord-4.2.3
246966 2.2.2/lib
234562 actionview-4.2.3
118650 newrelic_rpm-3.9.9.275
72424 rack-1.6.4
69359 nokogiri-1.6.6.2
43845 SomeApp/app
.....
allocated memory by file
-----------------------------------
689672 ~/gems/paperclip-4.3.0/lib/paperclip/interpolations.rb
224356 ~/gems/activesupport-
4.2.3/lib/active_support/core_ext/string/output_safety.rb
136744 ~/gems/actionpack-
4.2.3/lib/action_dispatch/routing/route_set.rb
104800 ~/.rbenv/versions/2.2.2/lib/ruby/2.2.0/erb.rb
84291 ~/gems/actionview-4.2.3/lib/action_view/helpers/tag_helper.rb
76272 ~/gems/actionpack-
4.2.3/lib/action_dispatch/journey/formatter.rb
53964 ~/gems/activerecord-
4.2.3/lib/active_record/connection_adapters/postgresql_adapter.rb
52145 ~/gems/rack-1.6.4/lib/rack/response.rb
43824
~/.rbenv/versions/2.2.2/lib/ruby/2.2.0/psych/scalar_scanner.rb
.....
allocated objects by gem
-----------------------------------
4321 paperclip-4.3.0
2322 activerecord-4.2.3
2300 actionpack-4.2.3
2082 actionview-4.2.3
1726 activesupport-4.2.3
1538 2.2.2/lib
981 newrelic_rpm-3.9.9.275またPaperclipがあります！出力の最初のセクション(allocated memory)の単位はバイトです。つまりPaperclipには、このリクエストで約1MBのメモリが割り当てられました。多いです。心配するほどのものかはわかりませんが。通常このビューを見ることは、メモリを大量に消費している箇所を発見するのに良い方法です(*6)。
*6 実際のRAMコストはここで計測されたものより少し高くなります。MRIヒープは隙間なく使われるわけではありません。
おっと、ところで、割り当て済み(allocated)とは、正確にはどのような意味なのでしょうか。memory_profilerは、 割り当て済み(allocated)オブジェクトと 保持済み(retained)オブジェクトを区別します。保持済みオブジェクトは、おそらく少なくとも次のガベージコレクションまで、リクエスト後も存在し続けます。その時、ガベージ・コレクトされるかもしれないし、されないかもしれません。
割り当て済みオブジェクトは、保持されるときと、されないときがあります。保持されないとき、それは一時変数で、処理が終わった時に自動的にRubyが破棄します。保持済みオブジェクトが本当に気をつけなければならないものです。
下にスクロールすると、同じ出力が表示されますが、保持済みオブジェクトのみが対象です。 この表示部分に注意を払ってください。リクエストが終わった後も、これらのオブジェクトはメモリに張り付いたままです。 メモリ・リークを探しているなら、この中のどこかにあります。
analyze-memory
pp=analyze-memoryがrack-mini-profiler バージョン0.9.6から追加されています。基本的なヒープの解析と、ヒープの中で最も大きな文字列を100番目までリストアップします。通常最も大きい文字列は、レスポンスです。
この出力の使い道がどのくらいあるかはまだわかりませんが、もし文字列のメモリ割り当てを追跡している場合は、役に立つかもしれません。
例外の追跡
Rubyで例外を発生させるのは、とても遅いことをご存知でしたか？そうなんです。最大32倍遅くなります。残念なことに一部の開発者とgemはフロー制御のために例外を使っています。 例えば、Rubyのstripe gemは、クレジットカード取引が拒否されたときに例外を発生します。
アプリケーションは通常のオペレーションで例外を発生するべきではありません。使用しているライブラリが、知らないうちに例外を発生しているかもしれません。(もちろんその場合、例外のキャッチもしています)もしあなたの環境で、例外の発生とキャッチが起こっているかもしれないと感じたら、pp=trace-exceptionsを試してみてください。
まとめ
以上でrack-mini-profilerの説明は終わりです。Rack/Rubyパフォーマンス最適化のための、スイス・アーミーナイフのように優れた機能の詳細な説明を、楽しんでいただけたでしょうか。以下は記事のまとめです。
■本当に正確なパフォーマンスの計測結果が得たい場合は、製品モードをローカル環境に設定し、rack-mini-profilerを製品モードで実行してください。
■スピード・バッジを使用して、リクエスト中に生成されるSQLクエリの数に注意してください。
■DOMContentLoadedまでの時間はフロント・エンドのパフォーマンスにとって重要です。 スピード・バッジをよく見て、1000msを超えないようにしてください。
■キャッシュは最初にやることではなく、最後の手段です。SQLクエリと不要なコードをできるだけ削除して、削除できないものをキャッシュしてください。
■メモリ・リークを追跡する場合には、製品モードでGCツールを使用してください。オブジェクトへのメモリ割り当てを追跡する、様々な機能が利用できます。
■例外は遅いです。 trace-exceptionsを使用して、例外を知らない間に発行したり、キャッチしていなか確認してください。
SHARE:
(各ＳＮＳのシェアボタン)
ウェブ・サイトを高速化したいですか？
私はネイト・ベルコペック Nate Berkopec（@nateberkopec）です。 フル・スタック・エンジニアの観点から、ウェブのパフォーマンス、主にフロント・エンドとRubyのバック・エンドについて、オンライン記事を書いています。 もし、この記事が気に入って、次の記事について知りたい場合は、下をクリックしてください。 毎週1通程度、Eメールを私から直接送ります。スパムではありません。控えめです。
(メールアドレス送信フォーム)
Railsパフォーマンス完全ガイド
私が書いた「Railsパフォーマンス完全ガイド」を見てください! Ruby on Railsアプリケーションをより速く、よりスケーラブルに、より簡単にメンテナンスするためのツールを提供する、フル・スタックコースです。 361ページのPDF、プライベートSlack、15時間以上のビデオ・コンテンツが含まれています。
