如何记录Ruby程序中调用的每个方法？

Question

我继承了一大堆Ruby代码,坦率地说,对于像我这样的凡人来说,几乎无法理解.它实际上是Rspec单元测试代码,但结构"非常不寻常"很好地说.

我希望能够做的是运行代码,并在某处记录以下信息:

• 每个被调用的方法,包括定义方法的类的名称,以及定义调用方法的文件名(是的,我们在多个不同的文件中定义了相同的类/方法,而且很难知道被调用的)
• (可选)传递给调用的每个方法的参数

有了这个,我可以开始尝试重构它.如果没有它,由于代码库的大小(20k +单元测试用例),将它理顺起来将是一项非常困难的任务.

我无法进入并对正在运行的代码执行批量编辑,因为当你甚至在它周围使用苛刻的语言时(即经常),它会中断.相反,我需要能够在现有状态下对代码进行检测,或者对现有的代码进行最小的更改.

有没有一种方法可以记录这种级别的详细信息,而无需对代码库进行大量更改？我已经看过Ruby分析器,看看它是否有用,它可能会有所帮助; 我很好奇是否有更好的方法(特别是记录包含调用方法的文件名).

提前致谢

Answer 1

这绝对是可能的 - 事实上,甚至还有一种方法!只需在要开始记录事物的点之前在代码中的某处添加:

set_trace_func proc { |event, file, line, id, binding, classname|
  printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}

你想要的秘诀来自于Kernel#set_trace_func,如上所述:

• set_trace_func(proc)=> proc
• set_trace_func(nil)=> nil

建立proc为跟踪处理程序,如果参数是,则禁用跟踪nil.proc最多需要六个参数:事件名称,文件名,行号,对象ID,绑定和类的名称.proc每当事件发生时调用.事件是:( c-call调用C语言例程),c-return(从C语言例程返回),call(调用Ruby方法),class(启动类或模块定义),end(完成类或模块定义),line(执行代码)在新行上),raise(引发异常),和return(从Ruby方法返回).在proc的上下文中禁用跟踪.

这是一个方便的例子:

class Test
  def test
    a = 1
    b = 2
  end
end

set_trace_func proc { |event, file, line, id, binding, classname|
  printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}

t = Test.new
t.test

(注意:irb除非你想要一个巨大的文本滚动屏幕,否则不要尝试这个.)结果输出是:

    line test.rb:11               false
  c-call test.rb:11        new    Class
  c-call test.rb:11 initialize   Object
c-return test.rb:11 initialize   Object
c-return test.rb:11        new    Class
    line test.rb:12               false
    call test.rb:2        test     Test
    line test.rb:3        test     Test
    line test.rb:4        test     Test
  return test.rb:4        test     Test

您可以使用上面的格式化字符串来获取您想要记录的结果(例如,听起来您只对call事件感兴趣).希望对所有这些单元测试进行排序有所帮助,并祝你好运!

Answer 2

最近,set_trace_func被弃用了:

注意:此方法已过时,请改用TracePoint.

我们可以使用TracePoint set_trace_func来代替:

trace = TracePoint.new(:call) do |tp|
  puts "#{tp.defined_class}##{tp.method_id} got called (#{tp.path}:#{tp.lineno})"
end

trace.enable
# do stuff here
trace.disable

这实际上甚至比set_trace_func您在方便时启用和禁用更强大.您可以选择性地挂钩以下事件::line, :class, :end, :call, :return, :c_call, :c_return, :raise, :b_call, :b_return, :thread_begin, :thread_end

这是一个完整的例子:

class MyClass
  def initialize
  end
  def y
    z
  end
  def z
   1 + 1
  end
end

trace = TracePoint.new(:call) do |tp|
  puts "#{tp.defined_class}##{tp.method_id} got called (#{tp.path}:#{tp.lineno})"
end

trace.enable # note
MyClass.new.y
trace.disable
  # MyClass#initialize got called (./trace.rb:4)
  # MyClass#y got called (./trace.rb:7)
  # MyClass#z got called (./trace.rb:10)

Answer 3

我想包括事件发生的秒数以及每个函数花费的时间

start = DateTime.now.strftime('%Q').to_i / 1000.0
set_trace_func proc { |event, file, line, id, binding, classname|
  now_ms = DateTime.now.strftime('%Q').to_i / 1000.0
  duration = '%.3f' % (now_ms - start)
  start = DateTime.now.strftime('%Q').to_i / 1000.0
  printf "%s %s %8s %s:%-2d %10s %8s\n", DateTime.now.strftime("%S.%L"), duration, event, file, line, id, classname
}

AdminUser.create(password: "password", password_confirmation: "password", email: email)

set_trace_func nil

我试图调试为什么创建用户和登录 ActiveAdmin 需要这么长时间。

05.761 0.000 c-return /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:51       to_s   String
05.761 0.000   c-call /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:51 __bc_crypt BCrypt::Engine
09.736 63.975 c-return /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:51 __bc_crypt BCrypt::Engine
09.736 0.000   return /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/engine.rb:59 hash_secret BCrypt::Engine
09.736 0.000   c-call /Users/nperry/.rvm/gems/ruby-2.1.2@rxair/gems/bcrypt-3.1.7/lib/bcrypt/password.rb:46        new    Class

由此我知道 Ruby 在 . 中花费了超过一分钟的时间__bc_crypt。