計測エンジニアになろうとしたら苦労したという記事を技術ブログに書いたのですが、技術的な部分を備忘録も兼ねてまとめておきます。
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 オプションが作動せずエラーが出るので、応急処置ではありますが以下のように最新版をインストールするのが丸いです。
gem 'stackprof', git: "git://github.com/tmm1/stackprof.git", branch: "master"
設定は、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カイゼンなんかが簡単にできるようになると優しい世の中ですね。