rblineprofでソースコードの行ごとの処理時間を計測する｜ほっこりZAICOエンジニアブログ【クラウド在庫管理ソフト(システム) zaico 】

ZAICOでは、Android・iOS・Rubyエンジニアを絶賛募集中です！詳しくは、採用ページをご覧ください。

現在もミャンマー国内のインターネットが不安定な状態になることがあり、現地にいる彼女とメッセンジャーアプリ等で連絡が取れず数年ぶりに国際電話を使って安否確認を行いました。

念の為、日本の電話番号を教えていて助かりました。

今回は知っていればパフォーマンス改善の時に助かるかもしれないrblineprofというgemの紹介をしたいと思います。

rblineprof

ソースコードの行ごとの処理時間を計測してくれます。

インストール

gem 'rblineprof'

サンプルプログラム

今回はこのようなサンプルプログラムを用意しました。

require 'sanitize'

def a(n)
  sleep 0.001
  "http://localhost/#{n}"
end

def b(url)
  %Q{#{url}}
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{#{url}}
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{#{url}}
                               | 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

sonots/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{#{url}}
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

peek/peek-rblineprof: Peek into how much each line of your Rails application takes throughout a request.

上記の方法でも十分使いやすくなったんですが毎回コードに変更を加えないといけないのは面倒ですよね。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の使い方を知っていれば特定の手助けをしてくれることでしょう。