Open11
stackprofを試してみる
shimopatastackporfについて
Profileできるgem
実行コードのうちどのメソッドが何回呼び出されたとかをレポートとして出力してくれる。
このレポートをもとにボトルネックとかを調査できるらしい。
shimopataruby単体で試してみる。リポジトリにサンプルがあるのでそれをコピペして手元で試してみる。
サンプルからちょっと変えてファイルをdumpするようにしてみた。
test.rb
require 'stackprof'
require 'date'
filename = File.basename(__FILE__)
class A
def initialize
pow
self.class.newobj
math
end
def pow
2 ** 100
end
def self.newobj
Object.new
Object.new
end
def math
2.times do
2 + 3 * 4 ^ 5 / 6
end
end
end
profile = StackProf.run(mode: :cpu, interval: 1000, out: "#{filename}_#{Time.now.to_i}.dump") do
1_000_000.times do
A.new
end
end
dumpの中身を見てみる。
❯ bundle exec stackprof sample.rb_1633759903.dump
==================================
Mode: cpu(1000)
Samples: 254 (0.00% miss rate)
GC: 35 (13.78%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
91 (35.8%) 91 (35.8%) A#pow
68 (26.8%) 68 (26.8%) A.newobj
49 (19.3%) 49 (19.3%) A#math
25 (9.8%) 25 (9.8%) (sweeping)
10 (3.9%) 10 (3.9%) (marking)
219 (86.2%) 6 (2.4%) block (2 levels) in <main>
213 (83.9%) 5 (2.0%) A#initialize
219 (86.2%) 0 (0.0%) block in <main>
219 (86.2%) 0 (0.0%) <main>
219 (86.2%) 0 (0.0%) <main>
35 (13.8%) 0 (0.0%) (garbage collection)
こんな感じに出力される。'pow'の方が'math'呼ばれている回数に比べて多いのが少し不思議。
コード上同じ回数呼ばれている様に見えるけど。実行時間とかも考慮されてるのかしら。
shimopataraw: true というoptionを追加するとグラフかできるっぽいのでやってみる
sample.rb
profile = StackProf.run(mode: :cpu, interval: 1000, out: "#{filename}_#{Time.now.to_i}.dump", raw: true) do
1_000_000.times do
A.new
end
end
やってみたが何も表示されない
bundle exec stackprof sample.rb_1633760549.dump > flamegraph
bundle exec stackprof --flamegraph-viewer=flamegraph
分からん、ruby単体だと使えんのかな
shimopata試行回数少なくするとプロファイル結果が出力されない。
sample
profile = StackProf.run(mode: :cpu, out: "#{filename}_#{Time.now.to_i}.dump") do
10.times do
A.new
end
end
❯ bundle exec stackprof test2.rb_1633761627.dump
==================================
Mode: cpu(1000)
Samples: 0 (NaN% miss rate)
GC: 0 (NaN%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
これはStackProfの実行時のオプションにintervalというのがあり多分この値を元にデータ取得しているんだと思う（デフォルトは1000。単位はmicroseconds） 。プロファイルするにはあるある程度実行時間を持たせる必要があるっぽい。
shimopatarailsで試してみる。
$ bundle exec rails .
$ bin/rails g scaffold user
gem 'stackprof'
user.tb
class User < ApplicationRecord
scope :hoge, -> { where(name: :hoge)}
def sample
puts self.name
sleep 0.5
end
end
script/user_sample.rb
class UserSample
def exec
StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump', raw: true) do
10000.times.each do
User.create(name: :hoge,age: 10)
end
end
end
def exec1
StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump', raw: true) do
100.times.each do
User.first.sample
end
end
end
end
UserSample.new.exec1
sleepを入れてボトルネックを擬似的に作成。
スクリプト実行してdumpファイル見てみる
$ bin/rails r script/user_create_and_find.rb
$ bundle exec stackprof tmp/stackprof-cpu-myapp.dump
==================================
Mode: cpu(1000)
Samples: 251 (1.18% miss rate)
GC: 59 (23.51%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
49 (19.5%) 49 (19.5%) (sweeping)
32 (12.7%) 32 (12.7%) ActiveSupport::Notifications::Event#now_cpu
30 (12.0%) 29 (11.6%) User#sample
19 (7.6%) 19 (7.6%) ActiveSupport::BacktraceCleaner#add_gem_filter
41 (16.3%) 18 (7.2%) ActiveRecord::LogSubscriber#log_query_source
13 (5.2%) 13 (5.2%) SQLite3::Statement#each
13 (5.2%) 12 (4.8%) Logger::LogDevice#write
10 (4.0%) 10 (4.0%) (marking)
9 (3.6%) 9 (3.6%) Bootsnap::CompileCache::ISeq.storage_to_output
4 (1.6%) 4 (1.6%) ActiveSupport::Notifications::Event#initialize
188 (74.9%) 3 (1.2%) Kernel#require_with_bootsnap_lfi
3 (1.2%) 2 (0.8%) Arel::Nodes::SelectCore#initialize
2 (0.8%) 2 (0.8%) ActiveRecord::Base.logger
11 (4.4%) 2 (0.8%) Bootsnap::CompileCache::ISeq.fetch
2 (0.8%) 2 (0.8%) Rails::BacktraceCleaner#initialize
2 (0.8%) 2 (0.8%) ActiveRecord::AttributeMethods.dangerous_attribute_methods
2 (0.8%) 2 (0.8%) Module#delegate
5 (2.0%) 2 (0.8%) Arel::Nodes::SelectStatement#initialize
2 (0.8%) 2 (0.8%) ActiveRecord::Core::ClassMethods#arel_table
2 (0.8%) 2 (0.8%) ActiveRecord::Result#hash_rows
2 (0.8%) 2 (0.8%) ActiveSupport::BacktraceCleaner#add_gem_silencer
2 (0.8%) 1 (0.4%) Listen::Directory.scan
12 (4.8%) 1 (0.4%) Bootsnap::CompileCache::ISeq::InstructionSequenceMixin#load_iseq
1 (0.4%) 1 (0.4%) ActiveModel::AttributeMethods::ClassMethods::CodeGenerator#execute
1 (0.4%) 1 (0.4%) Arel::Nodes::Binary#initialize
1 (0.4%) 1 (0.4%) Concurrent::Collection::NonConcurrentMapBackend#[]=
1 (0.4%) 1 (0.4%) Pathname#chop_basename
1 (0.4%) 1 (0.4%) ActiveRecord::Base.connection_handler
1 (0.4%) 1 (0.4%) Concurrent::Synchronization::MutexLockableObject#synchronize
1 (0.4%) 1 (0.4%) Logger::LogDevice#check_shift_log
User#sampleが上位に食い込んでるな。sleep入れて実行時間が伸びているからなのかな。
自作したクラスとかメソッドなら調査しやすそうだが、ActiveSupport::Notifications::Event#now_cpuとかにボトルネックがある場合はどうしてあげたらいいものか。
shimopataコマンド間違えてたわ 正しくは以下の通り。
bundle exec stackprof tmp/stackprof-cpu-myapp.dump --flamegraph > flamegraph
bundle exec stackprof --flamegraph-viewer=flamegraph
それっぽいグラフは見れる様になった。
shimopataこの記事読んでみる
shimopataこれで3d-flagmentを生成
bundle exec stackprof --d3-flamegraph tmp/stackprof-cpu-myapp.dump > stackprof.html
こんな感じのスクリプト追加してflamegraphを見てみる
user_sample.rb
def exec2
StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump', raw: true) do
100000.times.each do
User.where(name: :shio)
end
end
end
このままだとキャッシュ効いてSQL実行されなそうなので、キャッシュを無効化する。
user_sample.rb
def exec2
StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump', raw: true) do
100000.times.each do
User.uncached do
User.where(name: :shio)
end
end
end
end
このスクリプトのdumpを--d3-flamegraphで見てみる。
user_sample.rb の実行よりも上にあるやつを一つづつ見ていく。
そうするとwhereのところで70%となっており他のところに比べて負荷大きそう
ということでメモ化してみる。
user_sample.rb
def exec3
StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump', raw: true) do
user = nil
100000.times.each do
User.uncached do
user ||= User.where(name: :shio)
end
end
end
end
同じようにdumpを--d3-flamegraphで見てみる。
形変わった。whereの呼び出し回数減ってそう。
試しにBenchmarkをとってみる。
user_sample.rb
def exec4
Benchmark.bm(10) do |x|
x.report("before") do
100000.times do
User.uncached do
User.where(name: :shio)
end
end
end
user = nil
x.report("after") do
100000.times do
User.uncached do
user ||= User.where(name: :shio)
end
end
end
end
end
早くなってそう。
❯ bin/rails r script/user_sample.rb
Running via Spring preloader in process 84928
user system total real
before 4.541449 0.026729 4.568178 ( 4.578870)
after 0.536822 0.000819 0.537641 ( 0.538507)