Module#add_tracer

Ruby
1

Hi all.

Problem

Sometimes profiling of large library gives me results like:

% cumulative self self total
time seconds seconds calls ms/call ms/call name
…
10.60 2.20 0.38 210 1.81 6.45
Kernel.instance_eval
…

And I have a question “who had called Kernel#instance_eval so many
times?”

Solution

class Module
def add_tracer(meth)
m_alias = case meth
when :[] : “old_idx”
when :+ : “old_plus”
when :- : “old_minus”
#and so on
else ; “old_#{meth}”
end
module_eval %Q{
alias :#{m_alias} :#{meth}
def #{meth}(*arg, &block)
puts caller[0] + ": " + self.class.name + “##{meth} called”
#{m_alias}(*arg, &block)
end
}
end
end

Usage

Kernel.add_tracer(:instance_eval)
call_my_long_routine()

Which gives me desired information:
…
D:/tmp/test.rb:11:in `call_my_long_routine’: Object#instance_eval called
…

Isn’t it cool? :slight_smile:
Seriously, I think my solution has many drawbacks, but it helps me.
Maybe it will help somebody else.

Victor.

2

On May 10, 2006, at 6:45 PM, Victor S. wrote:

Kernel.instance_eval
when :[] : “old_idx”
end
…

-------------------------------------------------- Kernel#set_trace_func
set_trace_func(proc) => proc
set_trace_func(nil) => nil

  Establishes proc as the handler for tracing, or disables tracing
  if the parameter is nil. 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), and return (return from a Ruby method). Tracing is
  disabled within the context of 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

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

From: Logan C. [mailto:[email protected]]

module_eval %Q{

  set_trace_func(nil)     => nil

  Establishes proc as the handler for tracing, or disables tracing
  if the parameter is nil. proc takes up to six parameters: an event

Of cause I know about this. My solution is much more lightweight
(because
only one function of one class would be slow down).

Victor.

4

From: Logan C. [mailto:[email protected]]

  else ; "old_#{meth}"

Of cause I know about this. My solution is much more lightweight
(because
only one function of one class would be slow down).

Victor.

Yours also breaks when someone else overrides the same method and
aliases it to old_#{meth} (Which, unfortunately is pretty common.)

Yeah. It also breaks in dosens of other cases :slight_smile:
I’ve just show and idea.

But you’re quite right. Maybe I must say something like untraced_#{meth}

V

5

On May 10, 2006, at 7:34 PM, Victor S. wrote:

  #and so on

end

Of cause I know about this. My solution is much more lightweight
(because
only one function of one class would be slow down).

Victor.

Yours also breaks when someone else overrides the same method and
aliases it to old_#{meth} (Which, unfortunately is pretty common.)

6

On Thu, 2006-05-11 at 08:44 +0900, Logan C. wrote:

On May 10, 2006, at 7:34 PM, Victor S. wrote:

Of cause I know about this. My solution is much more lightweight
(because
only one function of one class would be slow down).

Yours also breaks when someone else overrides the same method and
aliases it to old_#{meth} (Which, unfortunately is pretty common.)

I’ve started aliasing like this:

__filename__methodname__

e.g, in foo.rb, it’d be foo__somemethod.

Not sure if it’s really much help when it comes to these problems, but
it seems like a good idea at the time :slight_smile:

7

On 5/10/06, Logan C. [email protected] wrote:

Yours also breaks when someone else overrides the same method and
aliases it to old_#{meth} (Which, unfortunately is pretty common.)

So does yours in many cases ;-). Imagine any code that uses
Binding.of_caller, debug, or profile to any significant extent… Here
are a few more advanced solutions (lacking in polish a little but that
is a task for the reader):

module Kernel
tracers = []
legacy_tracer = nil

set_trace_func lambda {|*args|
legacy_tracer.call(*args) if legacy_tracer

Might want to check line and file to match LINE and FILE

by the correct difference.

tracers.dup.each {|tracer| tracer.call(*args)} unless args[3] ==
:trace
}

define_method(:set_trace_func) {|proc|
legacy_tracer = proc
nil
}

Not thread safe but easy to make so.

define_method(:trace) {|tracer, block|
tracers << tracer
result = block.call

lambda {} == lambda {} work around just in case.

tracers.reject! {|x| x.object_id == tracer.object_id}
result
}
end

The above allows one to trace regions of code easily (still a bit
ugly… maybe keyword arguments and {||} style block construction would
help):

def selective_trace
result_of_the_traced_block = trace(lambda {|*a|
puts “Tracing code here”
}, lambda {
# code to trace here. You could pass a method in also.
# The Symbol#to_proc code might make that look even better.
})
end

… Not so much greater but it at least doesn’t let others clobber
tracers.

The other snippet is a cleanup of the original tracer code using
another technique. The unfortunate thing is that the clean version
only works in 1.9+ (block with blocks). There are workarounds I will
show but first the nice looking code:

class Module
def add_tracer(meth)
old_proc = instance_method(meth)

define_method(meth) { |*args, &block|
  puts caller[1] + ": " + self.class.name + "##{meth} called"
  old_proc.bind(self).call(*args, &block)
}

end
end

Note the lack of text eval (which is really a big plus IMO). 1.8 is a
sad story in this regard however (I wish Matz would allow 1.8 to take
block args in blocks somehow ~.^). The preservation of the method is
done in a hash rather than a lexical closure in 1.8’s case:

class Module

Simple tracer storage. This could be more elaborate.

class << self
attr_reader :tracers
end
@tracers = {}

Very similar to original code. Doesn’t clobber for

single level tracing (as in only calling add_tracer on

:foo once will preserve foo). More elaborate storage

could provide safety from multi-tracing but I couldn’t

think of a good use case.

def add_tracer(meth)
Module.tracers[meth] = instance_method(meth)
module_eval %{
def #{meth}(*args, &block)
puts caller[0] + ": " + self.class.name + “##{meth} called”
Module.tracers[:#{meth}].bind(self).call(*args, &block)
end
}
end
end

Note that this also resorts to text eval again. There are some really
complex (a.k.a. ugly) hacks to avoid this but I would rather have a
simple example. The conclusion is that there are plenty better options
than using alias and similar to accomplish this. Your best bet is
probably the one that best models the type and lifetime of your hook.
That can vary quite a bit from code to code so use your best judgement
and always have a generous amount of test code to ensure things stay
in line.

At least we can all look forward to the eventual release of Rite and
the 2.0 language. The older slides from his “How Ruby Sucks”
presentation (RUbyConf 03) [1] and the newer “Wild and Weird Ideas”
presentation (RubyConf 05) [2] show some possible ways 2.0 might
support wrapping method calls. If that doesn’t happen at least blocks
can take blocks right now in 1.9 ^^.

Brian.

[1] http://www.rubyist.net/~matz/slides/rc2003/mgp00028.html
[2] http://www.rubyist.net/~matz/slides/rc2005/mgp00033.html

8

You could use binding instead of aliasing which is safer albiet a bit
slower.