66
Help us understand the problem. What are the problem?

More than 5 years have passed since last update.

posted at

StackProfを使ってrubyプログラムのプロファイリングをする方法

計測エンジニアになろうとしたら苦労したという記事を技術ブログに書いたのですが、技術的な部分を備忘録も兼ねてまとめておきます。
Spring_MTさんのブログには大変お世話になりました。(というかREADME + このブログ記事のまとめでしかないような、、、汗)

profilingとは

プログラムが実行された際、どの部分のコードの実行にどれだけの時間がかかったのかを計測することです。
ではなぜ人はプロファイリングするのでしょうか?
プロファイリングはパフォーマンスのボトルネックを発見し、”遅いプログラムを速くする”手助けになります。プログラムの中で無駄に何度も呼ばれている部分、不要なのに呼びだされている部分、不自然に遅い部分を発見すれば、それを効率化することでプログラムの実行を速くすることができます。

StackProfとは

Rubyプログラムのプロファイリングに関してはいくつかのツールがありますが、その中でも軽量でかつ使いやすい、本番環境でも簡単に仕込めるという点で優れているのが tmm1/stackprof です。Rubykaigi2014で発表されて少し有名になりました。

これは ruby2.1 以降で導入された、rb_profile_frames という軽量なC APIを用いたミドルウェアのプロファイラで、graphviz, flamegraph といった可視化コマンドも内部に持っています。

StackProfの使い方

Bundlerを使っていれば、Gemfileに追記してbundle installすればインストールできます。ただしリリース版(v0.2.7)は若干古く、後述の--flamegraph オプションが作動せずエラーが出るので、応急処置ではありますが以下のように最新版をインストールするのが丸いです。

Gemfile
  gem 'stackprof', git: "git://github.com/tmm1/stackprof.git", branch: "master"

設定は、config.ru以下に書きます。設定は以下の通りやると便利です。

config.ru
require ::File.expand_path('../config/environment',  __FILE__)

is_stackprof         =  ENV['ENABLE_STACKPROF'].to_i.nonzero?
stackprof_mode       = (ENV['STACKPROF_MODE']       || :wall).to_sym
stackprof_interval   = (ENV['STACKPROF_INTERVAL']   || 1000).to_i
stackprof_save_every = (ENV['STACKPROF_SAVE_EVERY'] || 1 ).to_i
stackprof_path       =  ENV['STACKPROF_PATH']       || 'tmp/stackprof/'
use StackProf::Middleware, enabled:    is_stackprof,
                           mode:       stackprof_mode,
                           raw:        true,
                           interval:   stackprof_interval,
                           save_every: stackprof_save_every,
                           path:       stackprof_path

run Rails.application

このように書くことでミドルウェアとしてstackprofを使うことができます。
以下、オプション(enabled, mode, raw, interval, save_every, path)の解説です。

enabled

これはStackProfを起動するかどうかを表します。これは環境変数$ENABLE_STACKPROFの$0 / 1$で判定します。export ENABLE_STACKPROF=1として、rails sすればOKです。

また、わざわざrailsを再起動しなくてもStackProfの有効/無効はコンソールから変更することができます。

StackProf.running?
StackProf.start
StackProf.stop

の3つのコマンドがあります。running?メソッドはStackProfが起動中かを判定します。start, stopは名前の通りです。
このように手軽に本番環境でプロファイルをON⇔OFFと切り替えることができるのが便利です。

mode

よく使われるのは[:cpu, :wall]の2つでしょう。wallは全体での実行時間、cpuはCPU時間=CPUでの処理の実行時間のみを計測します。

raw

後述する--flamegraphオプションを利用するために必要です。trueにしておきましょう。

interval

計測タイミングの粒度です。デフォルトは1000[μs] = 1[ms] になっています。

save_every

何リクエストごとにプロファイル結果をdumpファイルで出力するか、です。毎回のリクエストごとに生成したいときは1にするといいですが出力されすぎる可能性があるので注意。

path

dumpファイルを出力するディレクトリです。tmp/stackprof/以下にでも入れておけばいいでしょう。

実際に使ってみる

本番環境で準備が整ったらStackProf.startを手動で実行。やめたくなったらStackProf.stopで止めればOK。
すると先ほどpathオプションで設定したtmp/stackprof/以下にdumpファイルが生成されています。

$ ll -h tmp/stackprof/stackprof-wall-*.dump
-rw-r--r--  1 Shunsuke_SAKAI  staff   2.7M 12  9 08:40 tmp/stackprof/stackprof-wall-1416-1449618032.dump
-rw-r--r--  1 Shunsuke_SAKAI  staff   197K 12  9 01:00 tmp/stackprof/stackprof-wall-40150-1449590403.dump

この出力結果を見るには

$ bundle exec stackprof tmp/stackprof/hogehoge.dump

とすると、

==================================
  Mode: wall(1000)
  Samples: 499 (3.29% miss rate)
  GC: 89 (17.84%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       129  (25.9%)         129  (25.9%)     block in WEBrick::GenericServer#start
        27   (5.4%)          27   (5.4%)     Rack::MiniProfiler.config
        24   (4.8%)          24   (4.8%)     block (2 levels) in Rack::MiniProfiler::TimerStruct::Sql#initialize
        22   (4.4%)          22   (4.4%)     block in Mysql2::Client#query
        11   (2.2%)           9   (1.8%)     block in Bullet::Detector::NPlusOneQuery.caller_in_project
         9   (1.8%)           9   (1.8%)     Rabl::Sources#fetch_manual_template
         8   (1.6%)           8   (1.6%)     Rabl::Engine#attribute
         7   (1.4%)           7   (1.4%)     block in Fog::AWS::SignatureV4#canonical_path
         7   (1.4%)           5   (1.0%)     #<Module:0x007ffa544e1ff0>.escape
         4   (0.8%)           4   (0.8%)     Time#compare_with_coercion
         4   (0.8%)           4   (0.8%)     ActiveSupport::PerThreadRegistry#instance
         4   (0.8%)           4   (0.8%)     Rabl::Engine#child
         3   (0.6%)           3   (0.6%)     Rabl::Engine#initialize
         3   (0.6%)           3   (0.6%)     Fog::HMAC#setup_sha256
         3   (0.6%)           3   (0.6%)     block in ActiveSupport::FileUpdateChecker#max_mtime

のように出力結果が表示されます。
呼ばれた回数、及びそれが全体の実行時間のうちどれくらいの割合を占めるのか、を見ることができます。ここのオプション--limitを用いることでもっと深くまで表示することができます(デフォルトは30)。

細かく見たい場合はメソッド名を引数にとり、それがどこで呼ばれているかを確かめることができます。

$ bundle exec stackprof tmp/stackprof/stackprof-wall-5348-1449630859.dump --method "Mysql2::Client#query"
block in Mysql2::Client#query (/usr/local/Cellar/rbenv/0.4.0/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-mini-profiler-0.9.3/lib/patches/db/mysql2.rb:22)
  samples:    22 self (4.4%)  /     22 total (4.4%)
  callers:
      22  (  100.0%)  SqlPatches.record_sql
  code:
                                  |    22  |     result, record = SqlPatches.record_sql( args[0] ) do
   22    (4.4%) /    22   (4.4%)  |    23  |       query_without_profiling(*args,&blk)
                                  |    24  |     end
Mysql2::Client#query (/usr/local/Cellar/rbenv/0.4.0/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-mini-profiler-0.9.3/lib/patches/db/mysql2.rb:19)
  samples:     2 self (0.4%)  /     78 total (15.6%)
  callers:
      78  (  100.0%)  block in ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter#execute
  callees (76 total):
      76  (  100.0%)  SqlPatches.record_sql
  code:
                                  |    19  |   def query(*args,&blk)
                                  |    20  |     return query_without_profiling(*args,&blk) unless SqlPatches.should_measure?
                                  |    21  |
   76   (15.2%)                   |    22  |     result, record = SqlPatches.record_sql( args[0] ) do
                                  |    23  |       query_without_profiling(*args,&blk)
                                  |    24  |     end
                                  |    25  |     result.instance_variable_set("@miniprofiler_sql_id", record) if result
    2    (0.4%) /     2   (0.4%)  |    26  |     result
                                  |    27  |   end

可視化してみる

なんだかんだいってVisualizeできると喜んでしまうものです。硬派なプログラマの方はそうでもない?そうですか…

stackprof コマンドのオプションで --graphviz--flamegraphが指定できます。
前者はグラフ理論なんかでよく出てくる、ノードとエッジのアレです。
後者は直訳すると"炎のグラフ"となりますが、こちらの記事が詳しく、参考にするといいと思います。簡単に説明すると、横幅がかかった時間、縦方向の積み重ねがネストした関数呼び出しを表しています。横幅をとってしまう関数が遅くしている要因といえます。

flamegraphを出す

以下のようにすればOKです。

$ stackprof tmp/stackprof-wall-5348-1449630859.dump --flamegraph > tmp/fl.js
$ stackprof tmp/stackprof-wall-5348-1449630859.dump --flamegraph-viewer tmp/fl.js
open file:///Users/Shunsuke_SAKAI/.bundler/ruby/2.2.0/stackprof-e252254355f8/lib/stackprof/flamegraph/viewer.html?data=/path/to/your/tmp/fl.js

raw: trueを設定しておくのをお忘れなく。
これで出てきたファイルのリンクをブラウザで開くとflamegraphが表示されます。

最後に

プロファイラとベンチマークをうまく使うことで計測時間を出力し、パフォーマンスのボトルネック把握に役立てることができます。こうした計測ツールが流行って、重くなりがちなRailsアプリケーションの高速化によるUXカイゼンなんかが簡単にできるようになると優しい世の中ですね。

Register as a new user and use Qiita more conveniently

  1. You can follow users and tags
  2. you can stock useful information
  3. You can make editorial suggestions for articles
What you can do with signing up
66
Help us understand the problem. What are the problem?