# Module#add\_tracer

**URL:** <https://www.ruby-forum.com/t/module-add-tracer/60191>\
**Category:** Ruby\
**Created:** [May 11, 2006, 12:45am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191 "2006-05-11T00:45:51Z")\
**Posts on this page:** 8\
**Page:** 1

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 12:45am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/1 "2006-05-11T00:45:51Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 1:19am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/2 "2006-05-11T01:19:12Z")

</div>

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
```

---

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 1:37am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/3 "2006-05-11T01:37:41Z")

</div>

From: Logan C. [[mailto:removed\_email\_address@domain.invalid](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.

---

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 1:50am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/4 "2006-05-11T01:50:02Z")

</div>

From: Logan C. [[mailto:removed\_email\_address@domain.invalid](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

---

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 1:46am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/5 "2006-05-11T01:46:46Z")

</div>

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.)

---

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 9:20am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/6 "2006-05-11T09:20:21Z")

</div>

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 🙂

---

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 4:15am UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/7 "2006-05-11T04:15:50Z")

</div>

On 5/10/06, Logan C. [removed\_email\_address@domain.invalid](mailto: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](http://www.rubyist.net/~matz/slides/rc2003/mgp00028.html)  
[2] [http://www.rubyist.net/~matz/slides/rc2005/mgp00033.html](http://www.rubyist.net/~matz/slides/rc2005/mgp00033.html)

---

<div class="post-metadata">

**Author:** ![victor123789](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/v/f0a364/32.png) [@victor123789](https://www.ruby-forum.com/u/victor123789)\
**Post date:** [May 11, 2006, 7:09pm UTC](https://www.ruby-forum.com/t/module-add-tracer/60191/8 "2006-05-11T19:09:45Z")

</div>

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