How use Profiling, a Quick Guide

amin1426 · May 24, 2006, 12:10am

On Tue, 23 May 2006, Mark S. wrote:

Can anyone recommend some good or tutorials on profiling and benchmarking?
Although I have used them both (from the standard library), I feel I lack
fundamental knowledge about how to go about it.

I don’t know of any Good one but here are some things I do…

Always benchmark first, profile and optimize later. Otherwise you
don’t
know whether it was worth it. (Hint: Often the tweaks aren’t worth
it, or
make things worse)
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.)
Scan down the list for the first few user written methods. Usually
the one
that you spent the most time in has the most fat to trim.
Scan the list for the routine that took the longest (as opposed
to the most time spent in it.) Try get that one to just do less.
Use strace, see what the system is doing at an OS level. I once
improved another persons program (professional in production) by a
factor of 40, yes FORTY times, by noting it was doing an lseek on
every
record read and changing that to an mmap.
Always look out for surprises. The best moment in an optimizers life
is
when you look at something and say “WTF! Why is that routine
taking so
long!?”
Large number of calls to .size and .length and .count_objects
methods are a
clue some nidjit somewhere is doing something really N^2 stupid
like…
for( i=0; i < container.count_objects(); i++) {
}
Use top, vmstat, times as well.
Large usertime means optimize program.
Large system time means you really hammering the system calls (that
was a clue in the lseek case I mentioned above)
Large real time small user and system means you are waiting for
input from user / disk / network /…? Find out what.
Watch the page in page out stats. Watch the swap in swap out stats.
If you are paging or swapping, time to switch to memory consumption
optimization!
Use my memprofile / newprofile tricks to try spot the
http://wiki.rubygarden.org/Ruby/page/show/NewProfiler
http://rubyforge.org/snippet/detail.php?type=snippet&id=70

John C. Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : [email protected]
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.

amin1426 · May 24, 2006, 1:23am

On 5/23/06, John C. [email protected] wrote:

On Tue, 23 May 2006, Mark S. wrote:

Can anyone recommend some good or tutorials on profiling and benchmarking?
Although I have used them both (from the standard library), I feel I lack
fundamental knowledge about how to go about it.

Hmm, not sure how I missed the original message, but you might try:

http://www.ibm.com/developerworks/edu/os-dw-os-ruby2-i.html

(free subscription required)

amin1426 · May 24, 2006, 2:49am

On Wed, 24 May 2006, pat eyler wrote:

IBM Developer

(free subscription required)

Sigh! Buggy Registration required.

I came, I tried to register, made one error, back, fixed error, pressed
continue, nothing happened. nothing. nothing. click. CLICK
CLICK_CLICK-CLICK!

Stupid @%$#%#! Buggy dumb registration form!! AARGH!!

I went away.

DeveloperWorks used to be quite a Good resource.

On the web, better, less frustrating things are always just one click
away.

John C. Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : [email protected]
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.

amin1426 · May 24, 2006, 9:09am

From: John C. [mailto:[email protected]]
Sent: Wednesday, May 24, 2006 1:10 AM

On Tue, 23 May 2006, Mark S. wrote:

Can anyone recommend some good or tutorials on profiling and
benchmarking?
Although I have used them both (from the standard library), I feel I
lack
fundamental knowledge about how to go about it.

I don’t know of any Good one but here are some things I do…

Outstanding point! Some things that are worth mentioning:

Unfortuantely, Windows users have lack of Unix power tools, which are
always helpful for analysys. But some of them can be found at
http://gnuwin32.sourceforge.net/

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

Victor.

amin1426 · May 25, 2006, 1:16am

On Wed, 24 May 2006, Victor S. 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.

I’ll just stuff in something that histograms the call path to a certain
depth and that will be really really powerful.

Coming soon to a Ruby snippet near you…

John C. Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : [email protected]
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.

amin1426 · May 24, 2006, 6:34am

On 5/24/06, John C. [email protected] wrote:

On Wed, 24 May 2006, pat eyler wrote:

IBM Developer

Stupid @%$#%#! Buggy dumb registration form!! AARGH!!

I went away.

you need bugmenot.com.. with the Firefox extension.

amin1426 · May 25, 2006, 4:28am

On Thu, 25 May 2006, John C. wrote:

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 S.” 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 C. Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : [email protected]
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.

amin1426 · May 25, 2006, 3:32pm

From: Pedro Corte-Real [mailto:[email protected]]
Sent: Thursday, May 25, 2006 1:41 PM

def add_tracer(meth)
str = caller[0]+“-”+self.class.name+“-##{meth}”
Your code here
…

$traces.each {|name, value| puts “#{name} - #{value} calls”}

You can also sort it by the value in the hash to get an ordered list.
This will do for a hack but writing a tracing gem would be great.

Yep, it’s a very good point!

BTW, it can have sense to gather all those “profiling hacks” (like this
#add_tracer, and John’s NewProfile and memprofile) to some rubyforge
project?

amin1426 · May 25, 2006, 12:42pm

On 5/24/06, Victor S. [email protected] wrote:

Here can help my Module#add_tracer, described here
http://blade.nagaokaut.ac.jp/cgi-bin/scat.rb/ruby/ruby-talk/192291

That’s a nice idea. I made a small modification to count the totals of
each of the calling methods instead of printing each time:

$traces = Hash.new(0)

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)
str = caller[0]+“-”+self.class.name+“-##{meth}”
$traces[str] += 1
#{m_alias}(*arg, &block)
end
}
end
end

Array.add_tracer(:each)

…
Your code here
…

$traces.each {|name, value| puts “#{name} - #{value} calls”}

You can also sort it by the value in the hash to get an ordered list.
This will do for a hack but writing a tracing gem would be great.

Pedro.

amin1426 · May 25, 2006, 3:39pm

On 5/25/06, Victor S. [email protected] wrote:

BTW, it can have sense to gather all those “profiling hacks” (like this
#add_tracer, and John’s NewProfile and memprofile) to some rubyforge
project?

Yes, sure, it would be great to have some simple tracing tools that
one can use just by installing a gem.

Pedro.

amin1426 · May 25, 2006, 3:58pm

Victor S. [email protected] [060525 15:36]:

BTW, it can have sense to gather all those “profiling hacks” (like this
#add_tracer, and John’s NewProfile and memprofile) to some rubyforge
project?

code should go to rubyforge but the description of how to profile
brought up earlier in this thread should be on rubygarden:

http://wiki.rubygarden.org/Ruby/page/show/RubyOptimization

Hey, that’s what a wiki is for!

Cheers,

Steph.

amin1426 · May 25, 2006, 3:58pm

From: John C. [mailto:[email protected]]
Sent: Thursday, May 25, 2006 5:28 AM

Coool!! I like it! Let that be a lesson to those who say Ruby can’t do
===MethodTracer.rb========================================================
=======

[skip]

John, it’s really cool!
May be (as I’ve mentioned above) we can create “profile hacks” project
on
rubyforge?

Victor.

amin1426 · May 25, 2006, 3:42pm

----- Original Message -----
From: Pedro Côrte-Real [email protected]
Date: Thursday, May 25, 2006 12:41 pm
Subject: Re: How use Profiling, a Quick Guide.
To: [email protected] (ruby-talk ML)

def add_tracer(meth)
str = caller[0]+“-”+self.class.name+“-##{meth}”
Your code here
…

$traces.each {|name, value| puts “#{name} - #{value} calls”}

You can also sort it by the value in the hash to get an ordered list.
This will do for a hack but writing a tracing gem would be great.

Pedro.

Hi, this is interesting, and I tried something like it. It works fairly
well, but DON’T try to trace :+ with this, for obvious reasons… =)

/O

amin1426 · May 25, 2006, 4:01pm

From: [email protected] [mailto:[email protected]]
Sent: Thursday, May 25, 2006 4:56 PM

http://wiki.rubygarden.org/Ruby/page/show/RubyOptimization

Hey, that’s what a wiki is for!

Good point. Real problem is my very poor English. I’m afraid I can
easily
write something nobody can read

Steph.

Victor.

amin1426 · May 25, 2006, 5:38pm

From: Robert K. [mailto:[email protected]]
Sent: Thursday, May 25, 2006 6:33 PM

class Module
def #{meth}(*arg, &block)
…
Your code here
…

$traces.each {|name, value| puts “#{name} - #{value} calls”}

You can also sort it by the value in the hash to get an ordered list.
This will do for a hack but writing a tracing gem would be great.

Note that a similar thing can be achieved with set_trace_func

Drawbacks of set_trace_func was discussed in the original topic here:
http://blade.nagaokaut.ac.jp/cgi-bin/scat.rb/ruby/ruby-talk/192294

Victor.

amin1426 · May 25, 2006, 5:35pm

2006/5/25, Pedro Côrte-Real [email protected]:

def add_tracer(meth)
str = caller[0]+“-”+self.class.name+“-##{meth}”
Your code here
…

$traces.each {|name, value| puts “#{name} - #{value} calls”}

You can also sort it by the value in the hash to get an ordered list.
This will do for a hack but writing a tracing gem would be great.

Note that a similar thing can be achieved with set_trace_func

$ ruby -e ‘set_trace_func lambda {|*a| p a}; “”.length’
[“line”, “-e”, 1, nil, #Binding:0x100f6920, false]
[“c-call”, “-e”, 1, :length, #Binding:0x100f67b8, String]
[“c-return”, “-e”, 1, :length, #Binding:0x100f6770, String]

You just need to evaluate parameters appropriately. See also

http://ruby-doc.org/docs/ProgrammingRuby/html/ospace.html

Kind regards

robert

amin1426 · May 25, 2006, 9:47pm

On May 25, 2006, at 8:37 AM, Victor S. wrote:

From: Robert K. [mailto:[email protected]]

Note that a similar thing can be achieved with set_trace_func

Drawbacks of set_trace_func was discussed in the original topic here:
http://blade.nagaokaut.ac.jp/cgi-bin/scat.rb/ruby/ruby-talk/192294

Use event_hook instead. Its faster than both.

See zenprofile in ZenHacks for an example.

–
Eric H. - [email protected] - http://blog.segment7.net
This implementation is HODEL-HASH-9600 compliant

http://trackmap.robotcoop.com

amin1426 · May 26, 2006, 8:47am

On 5/25/06, Victor S. wrote:

[skip]

John, it’s really cool!
May be (as I’ve mentioned above) we can create “profile hacks” project on
rubyforge?

Can you call it “profiling” rather than “profile”? You could even
create such a project on RubyGarden instead of RubyForge initially.

amin1426 · May 26, 2006, 6:42am

On Thu, 25 May 2006, Victor S. wrote:

May be (as I’ve mentioned above) we can create “profile hacks” project on
rubyforge?

You welcome to.

I know unfortunately I’m somewhat overcommitted at the moment so I
probably won’t be able to do much on it. But you’re more than welcome to
grab my code and add it to such a project.

John C. Phone : (64)(3) 358 6639
Tait Electronics Fax : (64)(3) 359 4632
PO Box 1645 Christchurch Email : [email protected]
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.

amin1426 · May 26, 2006, 8:53am

From: [email protected] [mailto:[email protected]] On Behalf Of Dave
Burt
Sent: Friday, May 26, 2006 9:45 AM

On 5/25/06, Victor S. wrote:

[skip]

John, it’s really cool!
May be (as I’ve mentioned above) we can create “profile hacks” project
on
rubyforge?

Can you call it “profiling” rather than “profile”?

Thanks. And again, sorry for my English.

You could even
create such a project on RubyGarden instead of RubyForge initially.

Yes, makes sense. I’m planning to begin at Monday.

V.