Yuhei Okazaki

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

#ruby #isucon #performance #gem #estackprof

2021/09/29

Table of Contents

使い方
レポーティング
今後やりたいこと
まとめ

使い方

インストール

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 <main>(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 <main>
  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で出場する人のお供になると幸いです。私も、来年こそ本戦に進出できるよう、精進します。

Yuhei Okazaki

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

RubyKaigi 2024 参戦レポート - 沖縄でRubyistとアツい交流をしてきました！

#ruby #rubykaigi #okinawa

Yuhei Okazaki

2024/05/24

ISUCON12予選にチーム名:Gosicとして参戦しました

#isucon #performance #golang #sql

Yuhei Okazaki

2022/07/27

[Rails]CSVダウンロード機能を細部まで理解して実装する（２）Windows対応BOM付きUTF-8

#rails #ruby #csv #bom

kakudaisuke

2021/10/15

Fusic CLIを作りました！ - RubyでCLIを開発する

#ruby #cli #thor #aruba

Yuhei Okazaki

2021/09/10

[Rails] Deviseでメールアドレスを使わず別プロパティで認証し、パスワードリセットにも対応する

#rails #devise #ruby

yukabeoka

2021/06/07

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

使い方

インストール

Bundlerを使う場合

Bundlerを使わない場合

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

レポーティング

estackprof top

estackprof list

estackprof flamegraph

今後やりたいこと

まとめ

Yuhei Okazaki

Related Posts