From: John Carter <john.carter@...>
Date: 2006-05-25T11:28:00+09:00
Subject: MethodTracer.rb Re: How use Profiling, a Quick Guide.

On Thu, 25 May 2006, John Carter wrote:

> On Wed, 24 May 2006, Victor Shepelev wrote:
>
>>>   * Look at the top most items in the profile list. Usually they are
>>>     standard library functions. Silly things like [] or +...
>>>     Ask your self, "What could be calling these thing so often?
>>>     Can I make it do it less often? eg. Cache the result etc.)
>> 
>> Here can help my Module#add_tracer, described here
>> http://blade.nagaokaut.ac.jp/cgi-bin/scat.rb/ruby/ruby-talk/192291
> 
> Coool!! I _like_ it! Let that be a lesson to those who say Ruby can't do
> AOP or Lispish Macros.

LOVELY!

It works brilliantly! Just use -rprofile to find the hot spots, the
standard class.method that has been called many many many times and then
mixed in my little MethodTracer.rb

(Did you know Find.find invokes Kernel.catch once per file/directory?)

===MethodTracer.rb===============================================================

# Based on "Victor Shepelev" <vshepelev imho.com.ua> Ruby talk message.
# http://blade.nagaokaut.ac.jp/cgi-bin/scat.rb/ruby/ruby-talk/192291
#
#Usage
#-----
# Very simple
# require 'MethodTracer'
#
#SomeClass.add_tracer(:some_method)
#call_my_long_routine()
#SomeClass.report_tracer( :some_method)
#

$__tracer_no_recurse = nil
$__tracer_histogram = {}

# User configurable, tweak this for how many call frames you want in the profile.
$__tracer_histogram_depth = 3

class Module
   def report_tracer(meth)
     $__tracer_no_recurse = true
     trace_who = "#{to_s}.#{meth}"
     puts "Reporting hottest traces on '#{trace_who}'"
     raise "No tracer '#{trace_who}'" unless
       $__tracer_histogram.has_key? trace_who
     tracer = $__tracer_histogram[ trace_who]
     tracer.keys.sort_by{|k| -tracer[k]}.each do |k|
       printf "%s   %7d\n", k, tracer[k]
     end
     puts
     $__tracer_no_recurse = false
   end

   def add_tracer(meth)
     return if $__tracer_no_recurse
     $__tracer_no_recurse = true
     trace_who = "#{to_s}.#{meth}"
     puts "Adding tracer for '#{trace_who}'"

     raise "Already have a trace for #{trace_who}" if
       $__tracer_histogram.has_key? trace_who

     $__tracer_histogram[trace_who] = Hash.new(0)

     m_alias = case meth
       when :[] : "old_idx"
       when :+ : "old_plus"
       when :- : "old_minus"
       #and so on
       else ; "old_#{meth}"
     end

     to_eval = %Q{
       alias :#{m_alias} :#{meth}

       def #{meth}(*arg, &block)
         return #{m_alias}(*arg, &block) if $__tracer_no_recurse
         $__tracer_no_recurse = true
         begin
           path = caller[0..$__tracer_histogram_depth].join("\n")
           $__tracer_histogram["#{trace_who}"][path]+=1
           #{m_alias}(*arg, &block)
         ensure
           $__tracer_no_recurse = nil
         end
       end
     }

     #puts to_eval

     module_eval to_eval

     $__tracer_no_recurse = nil

   end
end

if $0 == __FILE__ then
   require 'test/unit'

   class TC_Tracer < Test::Unit::TestCase
     def try_a
       a = [1,2,3,4]
       puts a[2]
     end

     def try_b
       try_a
     end

     def try_c
       try_b
     end

     def foo
       try_b
       try_b
       try_b
       try_b
       try_b
       try_b
       try_b
       try_b
       try_b
       try_b
     end

     def test_trace
       Array.add_tracer(:[])
       try_c
       try_b
       try_a
       foo
       Array.report_tracer(:[])
     end
   end
end




John Carter                             Phone : (64)(3) 358 6639
Tait Electronics                        Fax   : (64)(3) 359 4632
PO Box 1645 Christchurch                Email : john.carter@tait.co.nz
New Zealand

Carter's Clarification of Murphy's Law.

"Things only ever go right so that they may go more spectacularly wrong later."

From this principle, all of life and physics may be deduced.