Forum: Ruby Module#add_tracer

Announcement (2017-05-07): www.ruby-forum.com is now read-only since I unfortunately do not have the time to support and maintain the forum any more. Please see rubyonrails.org/community and ruby-lang.org/en/community for other Rails- und Ruby-related community platforms.
Victor S. (Guest)
on 2006-05-11 02:45
(Received via mailing list)
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? :)
Seriously, I think my solution has many drawbacks, but it helps me.
Maybe it will help somebody else.

Victor.
Logan C. (Guest)
on 2006-05-11 03:19
(Received via mailing list)
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
Victor S. (Guest)
on 2006-05-11 03:37
(Received via mailing list)
From: Logan C. [mailto:removed_email_address@domain.invalid]
> >     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.
Logan C. (Guest)
on 2006-05-11 03:46
(Received via mailing list)
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.)
Victor S. (Guest)
on 2006-05-11 03:50
(Received via mailing list)
From: Logan C. [mailto:removed_email_address@domain.invalid]
> >>>       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 :)
I've just show and idea.

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

V
Brian M. (Guest)
on 2006-05-11 06:15
(Received via mailing list)
On 5/10/06, Logan C. <removed_email_address@domain.invalid> 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
Ross B. (Guest)
on 2006-05-11 11:20
(Received via mailing list)
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 :)
unknown (Guest)
on 2006-05-11 21:09
(Received via mailing list)
You could use binding instead of aliasing which is safer albiet a bit
slower.
This topic is locked and can not be replied to.