raise.d ruby*:::raise /pid == $1/ { class = copyinstr(arg0); source = copyinstr(arg1); printf("%s (%s:%d)", class, source, arg2); }

irb(main):001:0> $$ => 1985 irb(main):002:0> aho NameError: undefined local variable or method `aho' for main:Object from (irb):2 from :0

# dtrace -s raise.d 1985 dtrace: script 'raise.d' matched 2 probes CPU ID FUNCTION:NAME 1 41395 rb_longjmp:raise NameError ((irb):2) 1 41395 rb_longjmp:raise NameError (/usr/local/lib/ruby/1.8/irb/workspace.rb:81)

これは raise をプローブするだけの凄く単純な例だが、

• 事前に何も準備する必要がなく
• システムの不調を感じたときに
• その pid を指定するだけで
• エラーの発生箇所を外部から特定できる

という点で、既に十分実用的である。特に、例外を中途半端に rescue してログに「エラー」とだけ表示している場合のデバッグは非常にやっかいだが、そういう場合に、そのコードを修正することなく、それどころかアプリの停止すら必要なく、その発生箇所情報を取得できるのは非常に心強い。さらに、「pid の絞込み」部分の述語をなくすだけで、そのサーバの Ruby 監視ツールに早変わりする。(※1)

method.d

#pragma D option quiet

ruby$1:::function-entry
{
        self->ts = timestamp;
}

ruby$1:::function-return
/self->ts/
{
        @[copyinstr(arg0), copyinstr(arg1)] = sum(timestamp - self->ts);
        self->ts = 0;
}

END
{
        printf("%-15s %-20s %s\n", "Class", "Method", "Time");
        printa("%-15s %-20s %10@d\n", @);
}

# dtrace -s method.d 2035 ... Array shift 1079362 String gsub 1198380 String to_s 1457360 Hash []= 1481531 Module constants 2108975 Hash key? 5629032 TCPServer accept 352271736 Object sleep 2019952588

実行結果は、Scaffold(Rails) の list アクションを実行したときの、各メソッド毎の実行時間(nsec)である。これにより、高速化を目指すならば Hash#key? 付近に手を入れることになるが、TCP接続の前では誤差になることもわかる。

config/initializers/dtrace.rb

module DTracer
  module QueryProbe
    def self.included(base)
      base.class_eval <<-EOS
        alias_method :untraced_execute, :execute
        def traced_execute(sql, name=nil)
          Tracer.fire('query', sql) { untraced_execute(sql, name) }
        end
        alias_method :execute, :traced_execute
      EOS
    end
  end
end

ActiveRecord::Base.connection.class.class_eval do
  include DTracer::QueryProbe
end

(参考: http://dev.joyent.com/projects/ruby-dtrace/browse/ruby/examples/rails/dtrace_plugin )

ar.d ruby*:::ruby-probe /copyinstr(arg0) == "query-start"/ { self->qts = timestamp; } ruby*:::ruby-probe /copyinstr(arg0) == "query-end" && self->qts/ { query = copyinstr(arg1); @[query] = avg(timestamp - self->qts); self->qts = 0; }

% script/console >> Kid.count >> Kid.find(:all)

# dtrace -s ar.d SELECT * FROM kids 413311 SELECT count(*) AS count_all FROM kids 462813

Rails 全体のパフォーマンスを計測するツールを作りたい。