How use Profiling, a Quick Guide


#1

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 : removed_email_address@domain.invalid
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.


#2

On 5/23/06, John C. removed_email_address@domain.invalid 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)


#3

On Wed, 24 May 2006, pat eyler wrote:

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

(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 : removed_email_address@domain.invalid
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.


#4

From: John C. [mailto:removed_email_address@domain.invalid]
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:

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


#5

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 : removed_email_address@domain.invalid
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.


#6

On 5/24/06, John C. removed_email_address@domain.invalid wrote:

On Wed, 24 May 2006, pat eyler wrote:

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

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

I went away.

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

#7

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 : removed_email_address@domain.invalid
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.


#8

From: Pedro Corte-Real [mailto:removed_email_address@domain.invalid]
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?


#9

On 5/24/06, Victor S. removed_email_address@domain.invalid 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.


#10

On 5/25/06, Victor S. removed_email_address@domain.invalid 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.


#11

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! :sunglasses:

Cheers,

Steph.


#12

From: John C. [mailto:removed_email_address@domain.invalid]
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.


#13

----- Original Message -----
From: Pedro Côrte-Real removed_email_address@domain.invalid
Date: Thursday, May 25, 2006 12:41 pm
Subject: Re: How use Profiling, a Quick Guide.
To: removed_email_address@domain.invalid (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


#14

From: removed_email_address@domain.invalid [mailto:removed_email_address@domain.invalid]
Sent: Thursday, May 25, 2006 4:56 PM

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

Hey, that’s what a wiki is for! :sunglasses:

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

Steph.

Victor.


#15

From: Robert K. [mailto:removed_email_address@domain.invalid]
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.


#16

2006/5/25, Pedro Côrte-Real removed_email_address@domain.invalid:

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


#17

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

From: Robert K. [mailto:removed_email_address@domain.invalid]

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. - removed_email_address@domain.invalid - http://blog.segment7.net
This implementation is HODEL-HASH-9600 compliant

http://trackmap.robotcoop.com


#18

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.


#19

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 : removed_email_address@domain.invalid
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.


#20

From: removed_email_address@domain.invalid [mailto:removed_email_address@domain.invalid] 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.