追記 2014/09/21 FlameGraphの出し方を追記しました
追記 2017/08/13 stackprofの原理をまとめました。
rubykaigi 2014終わりましたね。
スタッフの皆様、本当にお疲れ様でした。
で、3日目のkeynoteを聞いて、stackprofは使いこなせんとあかんものやと思って、早速試してみました。
RubyKaigi 2014 | Ruby 2.1 in Production
stackprof
Gemfileにgem 'stackprof'って書いて、bundle installすればOKです。
サンプリング
sampleスクリプトはこちら
で、StackProf.runが入ってる場合と、入ってない場合の実行時間はこんな感じ
- 入っている場合
% time bundle exec rails runner script/stackprof_sample.rb bundle exec rails runner script/stackprof_sample.rb 10.49s user 2.42s system 88% cpu 14.626 total
- StackProf.runの部分をコメントアウト
% time bundle exec rails runner script/stackprof_sample.rb bundle exec rails runner script/stackprof_sample.rb 10.09s user 2.12s system 91% cpu 13.313 total
そんなに変わらない！
サンプリング結果
stackprofコマンドで確認できます。
% bundle exec stackprof tmp/stackprof-cpu-sample.dump
==================================
Mode: cpu(1000)
Samples: 2136 (0.05% miss rate)
GC: 229 (10.72%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
691 (32.4%) 691 (32.4%) #<Module:0x007fbfd1951828>.mechanism
664 (31.1%) 154 (7.2%) block in Psych::Visitors::ToRuby#revive_hash
133 (6.2%) 133 (6.2%) Psych::Nodes::Scalar#initialize
119 (5.6%) 119 (5.6%) Psych::ScalarScanner#tokenize
122 (5.7%) 82 (3.8%) block in ERB::Compiler#compile
1300 (60.9%) 62 (2.9%) Psych::Visitors::Visitor#visit
48 (2.2%) 48 (2.2%) Psych::Parser#initialize
45 (2.1%) 45 (2.1%) ERB::Compiler#content_dump
44 (2.1%) 44 (2.1%) Psych::Nodes::Node#initialize
323 (15.1%) 41 (1.9%) #<Module:0x007fbfd1279f78>.parse_stream
21 (1.0%) 21 (1.0%) block in Rails::Paths::Path#expanded
21 (1.0%) 21 (1.0%) Psych::ClassLoader#load
19 (0.9%) 19 (0.9%) Psych::TreeBuilder#pop
1869 (87.5%) 18 (0.8%) Rails::Application::Configuration#database_configuration
16 (0.7%) 16 (0.7%) ERB::Compiler::Buffer#close
15 (0.7%) 15 (0.7%) ERB::Compiler::Buffer#push
12 (0.6%) 12 (0.6%) Psych::Visitors::ToRuby#register
19 (0.9%) 11 (0.5%) Psych::TreeBuilder#alias
9 (0.4%) 9 (0.4%) Psych::Visitors::ToRuby#visit_Psych_Nodes_Alias
681 (31.9%) 9 (0.4%) Psych::Visitors::ToRuby#visit_Psych_Nodes_Mapping
25 (1.2%) 9 (0.4%) Psych::Nodes::Mapping#initialize
130 (6.1%) 8 (0.4%) ERB::Compiler::SimpleScanner2#scan
8 (0.4%) 8 (0.4%) Psych::Nodes::Alias#initialize
7 (0.3%) 7 (0.3%) Psych::ClassLoader#initialize
145 (6.8%) 5 (0.2%) Psych::Visitors::ToRuby#deserialize
138 (6.5%) 5 (0.2%) Psych::TreeBuilder#scalar
5 (0.2%) 5 (0.2%) ActiveRecord::Base.configurations
4 (0.2%) 4 (0.2%) Psych::TreeBuilder#push
4 (0.2%) 4 (0.2%) ActiveRecord::DynamicMatchers::Method.pattern
1304 (61.0%) 4 (0.2%) Psych::Visitors::ToRuby#accept
--limitオプションで、もっと深くまで確認できます。
で、サンプリング結果を見てみると、
TOTAL (pct) SAMPLES (pct) FRAME
691 (32.4%) 691 (32.4%) #<Module:0x007fbfd1951828>.mechanism
664 (31.1%) 154 (7.2%) block in Psych::Visitors::ToRuby#revive_hash
133 (6.2%) 133 (6.2%) Psych::Nodes::Scalar#initialize
例えば、ここの部分ですが、例えばPsych::Nodes::Scalar#initializeはこのスクリプトの中のcpu時間の6.2%を使用しているということが判明します。
(<Module:0x007fbfd1951828>.mechanismは何かわからない。。。)
で、今日のkeynoteにあったようなflamegraphを見る場合は、--flamegraphオプションをつければ良い模様
% bundle exec stackprof tmp/stackprof-cpu-sample.dump --flamegraph
/Users/hoge/foo/vendor/bundle/ruby/2.1.0/gems/stackprof-0.2.7/lib/stackprof/report.rb:83:in `print_flamegraph': profile does not include raw samples (RuntimeError)
from /Users/hoge/foo/vendor/bundle/ruby/2.1.0/gems/stackprof-0.2.7/bin/stackprof:60:in `<top (required)>'
from /Users/hoge/foo/vendor/bundle/ruby/2.1.0/bin/stackprof:23:in `load'
from /Users/hoge/foo/vendor/bundle/ruby/2.1.0/bin/stackprof:23:in `<main>'
むむむ、エラー。。。
ちょとぱっと分からんので、明日また調査してみる。
2014/09/21追記
FlameGraphの出し方分かりました。
scrpitのStackProf.runのオプションに、raw: trueの追加が必要そうです。
Flamegraph option is error. · Issue #33 · tmm1/stackprof · GitHub
スクリプトのの例はこちら。
見方は、スクリプトを動かして、reportを出した後に、
% bundle exec stackprof tmp/stackprof-cpu-sample_raw.dump --flamegraph > f.js % bundle exec stackprof tmp/stackprof-cpu-sample_raw.dump --flamegraph-viewer f.js open file:///Users/hoge/foo/vendor/bundle/ruby/2.1.0/gems/stackprof-0.2.7/lib/stackprof/flamegraph/viewer.html?data=/Users/hoge/foo/f.js
として、flamegraph-viewerででてきたURLにアクセスすれば下記のようにFlameGraphを見ることができます。
(openコマンドで開こうとすると、URLパラメーターがついてこないっぽい？？？)
raw: trueにしてもtext summaryもみれました。
% bundle exec stackprof tmp/stackprof-cpu-sample_raw.dump --limit 1
==================================
Mode: cpu(1000)
Samples: 2201 (0.05% miss rate)
GC: 240 (10.90%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
679 (30.8%) 679 (30.8%) #<Module:0x007fe7432f8190>.mechanism
なので、raw: trueはデフォルトでいれておいてよいかと思います。
できた！！
追記 2015/05/16
StackProf::Middleware でrawオプションが追加された！！
