How do I log every method that's called in a Ruby program?
I've inherited a large pile of Ruby code that's, frankly, close to impossible to understand for a mortal like myself. It's actually Rspec unit test code, but the structure is "highly unusual" to put it nicely.
What I'd like to be able to do is run the code, and have the following information logged somewhere:
- every method that gets invoked, including the name of the class that defines the method, and the filename where the invoked method has been defined (yep, we'开发者_运维问答ve got the same class/method defined in multiple different files, and it's tough to know which is being invoked)
- (optionally) the parameters passed to each method invoked
With that, I could start trying to refactor it. Without it, it's going to be a very difficult task to get it straightened out, due to the size of the code base (20k+ unit test cases).
I can't afford to go in and perform wholesale edits to the code being run, because it breaks when you even use harsh language around it (i.e. frequently). Instead, I need to be able to instrument the code in its existing state, or with minimal changes to what exists now.
Is there a way of logging this level of detail without making wholesale changes to the code base? I've had a look at the Ruby profiler to see if it could help, and it probably could; I'm curious if there's a better way (particularly logging the filename containing the invoked method).
Thanks in advance
This is definitely possible -- in fact, there's even a method for it! Just add this somewhere in your code before the point that you want to start logging things:
set_trace_func proc { |event, file, line, id, binding, classname|
printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}
The secret sauce you want comes from Kernel#set_trace_func
, as noted above:
- set_trace_func(proc) => proc
- set_trace_func(nil) => nil
Establishes
proc
as the handler for tracing, or disables tracing if the parameter isnil
.proc
takes up to six parameters: an event name, a filename, a line number, an object id, a binding, and the name of a class.proc
is invoked whenever an event occurs. Events are: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), andreturn
(return from a Ruby method). Tracing is disabled within the context of proc.
Here's a handy example:
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
(Note: don't try this in irb
unless you want a huge scrolling screen of text.) The resulting output is:
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
You can play around with the formatting string above to get just the results you want to log (for example, it sounds like you're only interested in call
events). Hope that helps, and good luck with sorting through all those unit tests!
Recently, set_trace_func
was deprecated:
Note: this method is obsolete, please use TracePoint instead.
We can use TracePoint, which backs set_trace_func
, instead:
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
This is actually even more powerful than set_trace_func
because you can enable and disable at your convenience. You can selectively hook into the following events: :line, :class, :end, :call, :return, :c_call, :c_return, :raise, :b_call, :b_return, :thread_begin, :thread_end
Here a full example:
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)
I wanted to include the seconds-past-the-minute the event happend at as well as how long was spent in each function
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
I was trying to debug why it took so long to create users and log into 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
And from that I know Ruby spent more than a minute in __bc_crypt
.
精彩评论