代码之家 › 专栏 › 技术社区 › monch1962

如何记录ruby程序中调用的每个方法?

methods logging ruby

monch1962 · 技术社区 · 15 年前

我继承了大量的ruby代码,坦白地说,对于像我这样的凡人来说,这几乎是不可能理解的。它实际上是rspec单元测试代码,但结构“非常不寻常”,放得很好。

我想做的是运行代码,并在某个地方记录以下信息:

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

有了它,我可以开始尝试重构它。没有它,由于代码库(20K+单元测试用例)的规模,要理顺它将是一项非常困难的任务。

我负担不起对正在运行的代码进行大规模的编辑,因为当你使用苛刻的语言(即经常使用)时,它就会崩溃。相反,我需要能够在代码的现有状态下插入代码,或者对现有状态进行最小的更改。

有没有一种方法可以在不对代码库进行大量更改的情况下记录这一级别的详细信息?我看了一下ruby profiler,看看它是否有帮助,而且可能有帮助;我很好奇是否有更好的方法(特别是记录包含被调用方法的文件名)。

提前谢谢

3 回复 | 直到 7 年前

John Feminella 15 年前

这是绝对可能的——事实上,甚至有一种方法!只需在代码中的某个位置添加此内容,然后再开始记录:

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 ,如上所述:

设置跟踪函数(proc)=>proc

设置跟踪函数(nil)=>nil

建立 proc 作为跟踪的处理程序,或者如果参数是 nil . 进程 最多包含六个参数:事件名、文件名、行号、对象ID、绑定和类的名称。 进程 在事件发生时调用。事件是: 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

您可以随意使用上面的格式化字符串来获得想要记录的结果(例如,听起来您只对 呼叫 事件)。希望这能有所帮助,祝你在所有的单元测试中都能顺利排序!

Motine 7 年前

最近, 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

这实际上比 设置跟踪函数 因为您可以在方便的时候启用和禁用。您可以有选择地钩住以下事件: :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)

Nate 10 年前

我想包括事件发生的那一分钟过去的秒数,以及在每个函数中花费的时间

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

从那我知道鲁比花了超过一分钟 __bc_crypt .