Fusic Tech Blog

Fusion of Society, IT and Culture

簡単に使えるRubyプロファイラ -  EstackprofというGem作りました
2021/09/28

簡単に使えるRubyプロファイラ - EstackprofというGem作りました

岡嵜です。

8月にISUCON11の予選が開催されましたね。私は例年通り実装言語:Rubyで参加し、今年も予選で敗退しました。反省会で毎年のように挙がる話の1つに「Rubyのプロファイラである StackProf の導入に手間取る」という話があります。

日常的に使っていれば手間取ることはないのですが、年に数回しかもISUCONのようなプレッシャーのかかる場面で使おうとすると、たいてい引数の仕様がわからなかったり渡す引数を間違えたりといった、本筋とは関係のないトラブルに見舞われます。

そこで、StackProfをラップして引数の仕様をできるだけシンプルにした Estackprof というGemを作ったのでご紹介します。

Estackprof

RubyGems.org

GitHub

使い方

インストール

Bundlerを使う場合

Gemfile

gem 'estackprof'

bundle install します。

$ bundle install

Bundlerを使わない場合

$ gem install estackprof

プロファイリングを有効化

StackProf同様、RackMiddlewareとしてアプリケーションに組み込むことができます。StackProfと同様のオプションをサポートしていますが、オプションを省略した場合にもデフォルト設定でいい感じに動作するようにしています。

以下、アプリケーションのソースコードへの記述例です。

app.rb

require 'estackprof'

use Estackprof::Middleware

# ...your rack application

レポーティング

アプリケーションを動作させたあと、以下のコマンドを実行することでプロファイリングの結果を確認できます。 EstackprofをBundlerでインストールした場合、コマンドの前に bundle exec を付与するのを忘れないようにしましょう。

StackProfの場合、必ずダンプファイルを指定する必要があったのですがEstackprofではダンプファイルの格納先をデフォルト ./tmp とすることで、ダンプファイルの指定を省略できるようにしています。もちろん、StackProf同様、ダンプファイルを指定することも可能です。

estackprof help
Commands:
  estackprof flamegraph [OPTIONS] [FILE]  # Generate and open flamegraph
  estackprof help [COMMAND]               # Describe available commands or one specific command
  estackprof list [OPTIONS] [FILE...]     # Display sample counts of each line
  estackprof top [OPTIONS] [FILE...]      # Report to top of methods
  estackprof version                      # version

Options:
  -d, [--debug], [--no-debug]  # debug mode

ここから、各コマンドの使い方を紹介していきます。

estackprof top

estackprof top コマンドを使うことで、各メソッド・ブロックに要している時間を確認できます。

$ estackprof top
==================================
  Mode: cpu(1000)
  Samples: 516 (0.00% miss rate)
  GC: 77 (14.92%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       434  (84.1%)         434  (84.1%)     Object#bubble_sort(example/app.rb:9)
        45   (8.7%)          45   (8.7%)     (sweeping)
        31   (6.0%)          31   (6.0%)     (marking)
         4   (0.8%)           4   (0.8%)     Integer#to_s
        77  (14.9%)           1   (0.2%)     (garbage collection)
         1   (0.2%)           1   (0.2%)     Module#===
       438  (84.9%)           0   (0.0%)     Sinatra::Base#route_eval(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1031)
       438  (84.9%)           0   (0.0%)     Sinatra::Base#process_route(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1040)
       439  (85.1%)           0   (0.0%)     Kernel#catch
       438  (84.9%)           0   (0.0%)     Array#each

本家のStackProfだとSinatraのハンドラとなっているブロックが block とだけ表示されて、どのハンドラが重いのか分かりづらいのですが、Estackprofではファイル名と行番号を表示するようカスタマイズしています。

-c オプションを使うと呼び出している別のメソッドを含めて、時間を確認できます。

$ estackprof top -c
==================================
  Mode: cpu(1000)
  Samples: 516 (0.00% miss rate)
  GC: 77 (14.92%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       439  (85.1%)           0   (0.0%)     Rack::MethodOverride#call(vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/method_override.rb:15)
       439  (85.1%)           0   (0.0%)     Sinatra::ExtendedRack#call(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:215)
       439  (85.1%)           0   (0.0%)     Sinatra::Wrapper#call(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1990)
       439  (85.1%)           0   (0.0%)     Sinatra::Base.call(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1541)
       439  (85.1%)           0   (0.0%)     Sinatra::Base.synchronize(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1765)
       439  (85.1%)           0   (0.0%)     Rack::Handler::WEBrick#service(vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/handler/webrick.rb:66)
       439  (85.1%)           0   (0.0%)     WEBrick::HTTPServer#service(vendor/bundle/ruby/3.0.0/gems/webrick-1.7.0/lib/webrick/httpserver.rb:125)
       439  (85.1%)           0   (0.0%)     WEBrick::HTTPServer#run(vendor/bundle/ruby/3.0.0/gems/webrick-1.7.0/lib/webrick/httpserver.rb:69)
       439  (85.1%)           0   (0.0%)     Kernel#catch
       439  (85.1%)           0   (0.0%)     WEBrick::GenericServer#start_thread(vendor/bundle/ruby/3.0.0/gems/webrick-1.7.0/lib/webrick/server.rb:288)

-p オプションを使うと特定のファイル名・メソッド名がパターンマッチした行のみフィルタリングできます。

$ estackprof top -p app.rb
==================================
  Mode: cpu(1000)
  Samples: 516 (0.00% miss rate)
  GC: 77 (14.92%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       434  (84.1%)         434  (84.1%)     Object#bubble_sort(example/app.rb:9)
       438  (84.9%)           0   (0.0%)     block in 
(example/app.rb:23

-l オプションを使うと表示行数を指定できます。

$ estackprof top -c -l 5
==================================
  Mode: cpu(1000)
  Samples: 516 (0.00% miss rate)
  GC: 77 (14.92%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       439  (85.1%)           0   (0.0%)     Rack::MethodOverride#call(vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/method_override.rb:15)
       439  (85.1%)           0   (0.0%)     Sinatra::ExtendedRack#call(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:215)
       439  (85.1%)           0   (0.0%)     Sinatra::Wrapper#call(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1990)
       439  (85.1%)           0   (0.0%)     Sinatra::Base.call(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1541)
       439  (85.1%)           0   (0.0%)     Sinatra::Base.synchronize(vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb:1765)

estackprof list

estackprof list コマンドを使うことで、ファイル・メソッドの各行に要している時間を確認できます。 オプションなしの場合はファイルごとのサマリを表示します。

$ estackprof list       
 1739  (337.0%) /   434  ( 84.1%)   /Users/yokazaki/src/github.com/fusic/estackprof/example/app.rb
 10526  (2039.9%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/base.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/stackprof-0.2.17/lib/stackprof/middleware.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-protection-2.1.0/lib/rack/protection/xss_header.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-protection-2.1.0/lib/rack/protection/path_traversal.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-protection-2.1.0/lib/rack/protection/json_csrf.rb
  878  (170.2%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-protection-2.1.0/lib/rack/protection/base.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-protection-2.1.0/lib/rack/protection/frame_options.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/logger.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/common_logger.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/head.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/method_override.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/sinatra-2.1.0/lib/sinatra/show_exceptions.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/handler/webrick.rb
  878  (170.2%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/webrick-1.7.0/lib/webrick/httpserver.rb
  439  ( 85.1%) /     0  (  0.0%)   /Users/yokazaki/src/github.com/fusic/estackprof/vendor/bundle/ruby/3.0.0/gems/webrick-1.7.0/lib/webrick/server.rb

-f オプションを使うことで特定のファイルを全行表示します。 バブルソートの Range#each がネストしている部分がCPU負荷を高めていることがわかりますね。

$ estackprof list -f app.rb
                                  |     1  | # frozen_string_literal: true
                                  |     2  | 
                                  |     3  | require 'sinatra'
                                  |     4  | require 'json'
                                  |     5  | require 'estackprof'
                                  |     6  | 
                                  |     7  | use Estackprof::Middleware
                                  |     8  | 
                                  |     9  | def bubble_sort(array)
                                  |    10  |   ary = array.dup
                                  |    11  |   pos_max = ary.size - 1
                                  |    12  | 
  434   (84.1%)                   |    13  |   (0...pos_max).each do |n|
  433   (83.9%)                   |    14  |     (0...(pos_max - n)).each do |ix|
                                  |    15  |       iy = ix + 1
  139   (26.9%) /   139  (26.9%)  |    16  |       ary[ix], ary[iy] = ary[iy], ary[ix] if ary[ix] > ary[iy]
  294   (57.0%) /   294  (57.0%)  |    17  |     end
    1    (0.2%) /     1   (0.2%)  |    18  |   end
                                  |    19  | 
                                  |    20  |   ary
                                  |    21  | end
                                  |    22  | 
                                  |    23  | get '/' do
                                  |    24  |   array = Array.new(1000) { rand(10_000) }
  438   (84.9%)                   |    25  |   bubble_sort(array).to_s
                                  |    26  | end

-m オプションを使うことで特定のメソッドのみ全行表示します。 こちらはメソッドの呼び出し元・呼び出し先も表示してくれます。

$ estackprof list -m bubble_sort
Object#bubble_sort (/Users/yokazaki/src/github.com/fusic/estackprof/example/app.rb:9)
  samples:   434 self (84.1%)  /    434 total (84.1%)
  callers:
     867  (  199.8%)  Range#each
     434  (  100.0%)  block in 
callees (0 total): 867 ( Inf%) Range#each code: | 9 | def bubble_sort(array) | 10 | ary = array.dup | 11 | pos_max = ary.size - 1 | 12 | 434 (84.1%) | 13 | (0...pos_max).each do |n| 433 (83.9%) | 14 | (0...(pos_max - n)).each do |ix| | 15 | iy = ix + 1 139 (26.9%) / 139 (26.9%) | 16 | ary[ix], ary[iy] = ary[iy], ary[ix] if ary[ix] > ary[iy] 294 (57.0%) / 294 (57.0%) | 17 | end 1 (0.2%) / 1 (0.2%) | 18 | end | 19 |

estackprof flamegraph

estackprof flamegraph コマンドを使うことで、フレームグラフを出力・表示できます。

フレームグラフは tmp/flamegraph.html に出力されるようにしており、ブラウザが使える環境であれば自動的にブラウザ起動・表示までしてくれます。

estackprof flamegraph         
/Users/yokazaki/src/github.com/fusic/estackprof/tmp/flamegraph.html

フレームグラフ

これも、ボトルネックを掴む手段として有益なのでISUCONに役立つと思います。

今後やりたいこと

ひとまず上記のような機能で公開していますが、需要がありそうなら以下のような機能にも対応したいです。

  • StackProf Web navigator でやっているような、プロファイリング結果を確認するWebアプリを起動できるようにする
  • いわゆる「コールグラフ」を出力できるようにする

まとめ

ISUCONにRubyで出場する人のお供になると幸いです。私も、来年こそ本戦に進出できるよう、精進します。

yuuu

yuuu

2018年の年明けに組込み畑からやってきた、2児の父 兼 Webエンジニアです。 mockmockの開発・運用を担当しており、組込みエンジニア時代の経験を活かしてデバイスをプログラミングしたり、簡易的なIoTシステムを作ったりしています。主な開発言語はRuby、時々Go。