- フルリモ/Ruby
- フルリモ/PdM
- エンタープライズCS
- 他28件の職種
- 開発
- ビジネス
- その他
(エンジニアブログ)rblineprofでソースコードの行ごとの処理時間を計測する
現在もミャンマー国内のインターネットが不安定な状態になることがあり、現地にいる彼女とメッセンジャーアプリ等で連絡が取れず数年ぶりに国際電話を使って安否確認を行いました。
念の為、日本の電話番号を教えていて助かりました。
今回は知っていればパフォーマンス改善の時に助かるかもしれないrblineprofというgemの紹介をしたいと思います。
rblineprof
mm1/rblineprof: line-profiler for ruby
ソースコードの行ごとの処理時間を計測してくれます。
インストール
gem 'rblineprof'
サンプルプログラム
今回はこのようなサンプルプログラムを用意しました。
require 'sanitize'
def a(n)
sleep 0.001
"http://localhost/#{n}"
end
def b(url)
%Q{<a href="#{url}">#{url}</a>}
end
def c(html)
Sanitize.clean(html)
end
10000.times do |n|
html = b(a(n))
c(html)
end
このプログラムを見てすぐにボトルネックになりそうな部分がありますね。他にもありそうですかね。
パフォーマンス改善する時にはどの部分がボトルネックになっているのか調べる事が大事で何となくでやっているとどれくらい改善されたのか分からなくなります。そういう時のために rblienprof を使います。
使い方
require 'rblineprof'
require 'sanitize'
def a(n)
sleep 0.001
"http://localhost/#{n}"
end
def b(url)
%Q{<a href="#{url}">#{url}</a>}
end
def c(html)
Sanitize.clean(html)
end
profile = lineprof(/./) do
10000.times do |n|
html = b(a(n))
c(html)
end
end
file = profile.keys.first
File.readlines(file).each_with_index do |line, num|
wall, cpu, calls, allocations = profile[file][num + 1]
if wall > 0 || cpu > 0 || calls > 0
printf(
"% 5.1fms + % 6.1fms (% 4d) | %s",
cpu / 1000.0,
(wall - cpu) / 1000.0,
calls,
line
)
else
printf " | %s", line
end
end
実行結果
どうでしょうか?最初に想像していた箇所がボトルネックになっていましたか?
CPU時間、アイドル時間、呼び出し回数がそれぞれ表示されているのが分かると思います。
これを見ればどこが遅いのか分かりやすくなりましたね。
| require 'rblineprof'
| require 'sanitize'
|
| def a(n)
338.6ms + 11513.4ms ( 10000) | sleep 0.001
36.9ms + 0.0ms ( 10000) | "http://localhost/#{n}"
| end
|
| def b(url)
| %Q{<a href="#{url}">#{url}</a>}
| end
|
| def c(html)
4092.7ms + 0.3ms ( 10000) | Sanitize.clean(html)
| end
|
| profile = lineprof(/./) do
4649.3ms + 11524.1ms ( 1) | 10000.times do |n|
487.9ms + 11523.9ms ( 20000) | html = b(a(n))
4123.5ms + 0.2ms ( 10000) | c(html)
| end
| end
|
| file = profile.keys.first
|
| File.readlines(file).each_with_index do |line, num|
| wall, cpu, calls, allocations = profile[file][num + 1]
|
| if wall > 0 || cpu > 0 || calls > 0
| printf(
| "% 5.1fms + % 6.1fms (% 4d) | %s",
| cpu / 1000.0,
| (wall - cpu) / 1000.0,
| calls,
| line
| )
| else
| printf " | %s", line
| end
| end
rblineprof-report
上記のコードでも十分便利でしたが結果をファイルに出力したいとかもっと手軽に使いたい時に「rblineprof-report」gemを使うと便利です。
インストール
gem 'rblineprof-report'
使い方
require 'rblineprof'
require 'rblineprof-report'
require 'sanitize'
def a(n)
sleep 0.001
"http://localhost/#{n}"
end
def b(url)
%Q{<a href="#{url}">#{url}</a>}
end
def c(html)
Sanitize.clean(html)
end
profile = lineprof(/main2\.rb/) do
10000.times do |n|
html = b(a(n))
c(html)
end
end
LineProf.report(profile)
これで最初の結果とほぼ同じものを出力してくれるようになります。
lineprof関数に計測対象を渡していますが下記のようにすることで全ての計測結果を出力してくれるようになります。
profile = lineprof(/./) do
結果をファイルに出力
ファイルに出力する時も簡単で out に出力先のパスを指定するだけです。何を修正した時にどのように改善されたのか記録として残しておくのは重要なのでファイルとして後で共有するのにも良さそうです。
LineProf.report(profile, out: '/path/to/file')
しきい値を変更
出力された結果には時間によって色が変わりますがそのしきい値を変更することが出来ます。
依存関係が広い時とかにある程度絞り込むのに役立つかもしれません。
LineProf.report(profile, threshods: {
LineProf::CRITICAL => 1000, # default: 50 (ms)
LineProf::WARNING => 100, # default: 5 (ms)
LineProf::NOMINAL => 10, # default: 0.2 (ms)
})
peek-rblineprof
上記の方法でも十分使いやすくなったんですが毎回コードに変更を加えないといけないのは面倒ですよね。Railsアプリケーション向けにそれを解消してくれるのが「peek-rblineprof」gemです。
インストール
gem 'peek-rblineprof'
セットアップ
config/initializers/peek.rb
Peek.into Peek::Views::Rblineprof
assets/javascripts/application.js
//= require peek
//= peek/views/rblienprof
assets/javascripts/application.css
/*
*= require peek
*= require peek/views/rblineprof
*/
コードハイライトを有効にする場合
Gemfile
gem 'pygments.rb', require: false
assets/javascripts/application.css
/*
*= require peek
*= require peek/views/rblineprof
*= require peek/views/rblineprof/pygments
*/
使い方
後はRailsアプリケーションを起動して下記のように好きな画面にパラメータ付きでアクセスすると先程のような結果をその場で見ることが出来ます。
http://localhost:3000/?lineprofiler=views&lineprofiler_mode=cpu
lineprofiler
パラメータに応じて計測範囲を指定出来ます。
- app: Rails.root/(app|lib)
- views: Rails.root/app/view
- gems: Rails.root/vendor/gems
- all: Rails.root
- stdlib
lineprofiler_mode
基本的にはcpuのみ指定しておけば問題ないと思います。
CPU時間とアイドル時間を分けて出力する必要がなければ walls を使っても良いかもしれません。
- cpu: CPU時間、アイドル時間
- walls: 経過時間
まとめ
いかがだったでしょうか?
小さなプログラムであればボトルネックの特定も難しくないかもしれませんが実際の業務で使われているコードだと範囲も広くコード量も多くなりがちなので感覚的に見つけるのは難しくなります。
そういう時に今回のようなgemの使い方を知っていれば特定の手助けをしてくれることでしょう。