コードに大きな変更を加えずに実行時間を計測するRubyスクリプトの例

SQLを使ったコードを書いていると、PreparedStatementがガンガン増えるので、 実行時間を計測するコードを書くのが結構面倒になります。

コードに散らばったPreparedStatementにBenchmarkやTime.nowを仕込むのは苦行です。 そんな時は以下のようにPreparedStatementにフックするクラスを用意すると計測が楽になるのかな。

require 'sqlite3'

class Statement
  @@total_time ||= 0.0
  @@list ||= {}
  attr_accessor :stmt, :name
  def initialize(stmt, name)
    @stmt = stmt
    @name = name
    @@list[name] = [0.0, 0]  # time, count
  end

  # def method_missing(name, *args)
  def execute!(*args)
    t = Time.now
    # @stmt.send(name, *args)
    result = @stmt.execute!(*args)
    t = Time.now - t

    @@total_time += t
    prev_t, prev_count = @@list[@name]
    @@list[@name] = [prev_t + t, prev_count + 1]
    return result
  end

  def self.total_time; @@total_time; end
  def self.list; @@list; end
end


db = SQLite3::Database.new('test.sqlite')
stmt1 = db.prepare('SELECT * FROM tables')
stmt2 = db.prepare('SELECT foo,bar FROM tables WHERE id=? LIMIT 1')
stmt3 = db.prepare('SELECT * FROM tables WHERE id=?')

#----- 変更はここだけ
script_time = Time.now
stmt1 = Statement.new(stmt1, :stmt1)
stmt2 = Statement.new(stmt2, :stmt2)
stmt3 = Statement.new(stmt3, :stmt3)

# スクリプト全体の実行時間を計測&表示
at_exit {
  puts "name, total, count, avg"
  puts "script, #{(Time.now - script_time).round(6)},,"
  puts "sqlite, #{(Statement.total_time).round(6)},,"
  Statement.list.each {|name, (time, count)|
    puts "#{name}, #{time.round(6)}, #{count}, #{(time/count).round(6)}"
  }
}
#-----

100.times {
  stmt1.execute!
  stmt2.execute!(123)
  stmt3.execute!(456)
}

出力は適当なのでそのままだと見にくいですが、csviewerを使うとこんな感じで表示できます。

$ ruby test.rb | csviewer
+--------+-----------+--------+-----------+
|  NAME  |   TOTAL   | COUNT  |    AVG    |
+--------+-----------+--------+-----------+
| script |  2.956297 |        |           |
| sqlite |  2.953417 |        |           |
| stmt1  |  1.148423 |    100 |  0.011484 |
| stmt2  |  0.008129 |    100 |  8.1e-05  |
| stmt3  |  1.796866 |    100 |  0.017969 |
+--------+-----------+--------+-----------+

今回はexecute!メソッドだけにフックする例を取り上げてみましたが、この登録さえ面倒な場合はコメントアウトしてあるmethod_missingのコードですべてのメソッドにフックすると良いです。このコードは汎用ライブラリとしても使えますが、不要なメソッドまで測定してしまう可能性もあり、実行速度が落ちるデメリットもあります。

Rubyでは意外と使い回せそうなコードなのでコピペ用にメモしておきます。