CubicLouve

Spring_MTの技術ブログ

stackprofを使ってみる

追記 2014/09/21 FlameGraphの出し方を追記しました

追記 2017/08/13 stackprofの原理をまとめました。

spring-mt.hatenablog.com

rubykaigi 2014終わりましたね。

スタッフの皆様、本当にお疲れ様でした。

で、3日目のkeynoteを聞いて、stackprofは使いこなせんとあかんものやと思って、早速試してみました。

RubyKaigi 2014 | Ruby 2.1 in Production

stackprof

Gemfileにgem 'stackprof'って書いて、bundle installすればOKです。

サンプリング

sampleスクリプトはこちら

sample stackprof

で、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
 % 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

スクリプトのの例はこちら。

sample flamegraph

見方は、スクリプトを動かして、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パラメーターがついてこないっぽい???)

f:id:Spring_MT:20140921174339p:plain

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オプションが追加された!!

github.com