Ruby trace function

November 12, 2016 11:08


set_trace_func 方法可以收到很多代码执行事件,下面列出所有的事件,

name desc
c-call call a C-language routine
c-return return from a C-language routine
call call a Ruby method
class start a class or module definition
end finish a class or module definition
line execute code on a new line
raise raise an exception
return return from a Ruby method

通过此回调,我们可以统计出所有方法的调用层级关系、计算调用过程中产生的资源消耗(比如内存、时间),或是方法的调用次数等,下面给出一个简单统计方法调用耗时的使用例子

$time_list = []
set_trace_func(Proc.new do |event, file, line, id, binding, classname|
  case event
  when 'call', 'c-call' # 开始调用一个方法
    puts "#{event} #{file}:#{line} #{classname}\##{id}"
    $time_list << Time.now
  when 'return', 'c-return' # 方法调用结束
    next if $time_list.empty?
    puts "#{event} #{file}:#{line} #{classname}\##{id} #{(Time.now - $time_list.pop) * 1000}"
  end
end)

class A
  def initialize
    @a = 1
  end

  def p
    print "@a: #{@a}\n"
  end

  def s
    sleep 1
    s2
  end

  def s2
    sleep 0.5
  end
end

a = A.new
a.p
a.s
a.s2

执行结果:

c-call trace_func.rb:13 Class#inherited
c-return trace_func.rb:13 Class#inherited 0.003
c-call trace_func.rb:14 Module#method_added
c-return trace_func.rb:14 Module#method_added 0.002
c-call trace_func.rb:18 Module#method_added
c-return trace_func.rb:18 Module#method_added 0.002
c-call trace_func.rb:22 Module#method_added
c-return trace_func.rb:22 Module#method_added 0.001
c-call trace_func.rb:27 Module#method_added
c-return trace_func.rb:27 Module#method_added 0.001
c-call trace_func.rb:32 Class#new
call trace_func.rb:14 A#initialize
return trace_func.rb:16 A#initialize 0.003
c-return trace_func.rb:32 Class#new 0.016
call trace_func.rb:18 A#p
c-call trace_func.rb:19 Fixnum#to_s
c-return trace_func.rb:19 Fixnum#to_s 0.002
c-call trace_func.rb:19 Kernel#print
c-call trace_func.rb:19 IO#write
@a: 1
c-return trace_func.rb:19 IO#write 0.003
c-return trace_func.rb:19 Kernel#print 0.017
return trace_func.rb:20 A#p 0.078
call trace_func.rb:22 A#s
c-call trace_func.rb:23 Kernel#sleep
c-return trace_func.rb:23 Kernel#sleep 1000.5889999999999
call trace_func.rb:27 A#s2
c-call trace_func.rb:28 Kernel#sleep
c-return trace_func.rb:28 Kernel#sleep 500.766
return trace_func.rb:29 A#s2 500.87000000000006
return trace_func.rb:25 A#s 1501.6480000000001
call trace_func.rb:27 A#s2
c-call trace_func.rb:28 Kernel#sleep
c-return trace_func.rb:28 Kernel#sleep 504.88100000000003
return trace_func.rb:29 A#s2 504.953

从结果中可以看到,A#p 在很短的时间中就执行完了,A#sA#s2 他们 sleep 的一段时间也被计算出来

Comments: