profile

[Joe Van Dyk]

Hi,

Still pretty new to Ruby and profiling. Are there any tools I can use to
analyze my Ruby program to see where it's spending the bulk of the CPU time?

Thanks,
Joe

 

[Joe Van Dyk]

Hi,

Still pretty new to Ruby and profiling. Are there any
tools I can use to analyze my Ruby program to see where
it's spending the bulk of the CPU time?

Thanks,
Joe

I found the '-r profile' option. Are there any better tools out there?

 

[Zach Dennis]

Hi,

Still pretty new to Ruby and profiling. Are there any tools I can use to
analyze my Ruby program to see where it's spending the bulk of the CPU time?

http://www.rubygarden.org/ruby?Ruby_Profiler

zach

 

[Brian Schröder]

Hi,

Still pretty new to Ruby and profiling. Are there any tools I can use to
analyze my Ruby program to see where it's spending the bulk of the CPU time?

Thanks,
Joe

ruby -rprofile -e'puts (1..200).inject(0) { | r, i | r + (-1)**i * 1.0 / i }'
-0.690653430481824
% cumulative self self total
time seconds seconds calls ms/call ms/call name
44.44 0.04 0.04 1 40.00 80.00 Range#each
22.22 0.06 0.02 200 0.10 0.10 Fixnum#**
22.22 0.08 0.02 200 0.10 0.10 Float#/
0.00 0.08 0.00 1 0.00 0.00 Fixnum#+
0.00 0.08 0.00 200 0.00 0.00 Fixnum#*
0.00 0.08 0.00 1 0.00 0.00 Kernel.puts
0.00 0.08 0.00 2 0.00 0.00 IO#write
0.00 0.08 0.00 199 0.00 0.00 Float#+
0.00 0.08 0.00 1 0.00 80.00 Enumerable.inject
0.00 0.08 0.00 1 0.00 90.00 #toplevel
0.00 0.08 0.00 1 0.00 0.00 Profiler__.start_profile
0.00 0.08 0.00 1 0.00 0.00 Float#to_s

 

[Florian Gross]

I found the '-r profile' option. Are there any better tools out there?

What new features would they provide?

 

[Robert Klemme]

ruby -rprofile -e'puts (1..200).inject(0) { | r, i | r + (-1)**i * 1.0 / i }'
-0.690653430481824
% cumulative self self total
time seconds seconds calls ms/call ms/call name
44.44 0.04 0.04 1 40.00 80.00 Range#each
22.22 0.06 0.02 200 0.10 0.10 Fixnum#**
22.22 0.08 0.02 200 0.10 0.10 Float#/
0.00 0.08 0.00 1 0.00 0.00 Fixnum#+
0.00 0.08 0.00 200 0.00 0.00 Fixnum#*
0.00 0.08 0.00 1 0.00 0.00 Kernel.puts
0.00 0.08 0.00 2 0.00 0.00 IO#write
0.00 0.08 0.00 199 0.00 0.00 Float#+
0.00 0.08 0.00 1 0.00 80.00 Enumerable.inject
0.00 0.08 0.00 1 0.00 90.00 #toplevel
0.00 0.08 0.00 1 0.00 0.00 Profiler__.start_profile
0.00 0.08 0.00 1 0.00 0.00 Float#to_s

And an example for benchmark usage:

require 'benchmark'
include Benchmark

N = 10000
sample = ("foulx" * 100).freeze

bm(20) do |b|
b.report("gsub!") do
N.times do
s = sample.dup
s.gsub!(/x/, 'u')
end
end

b.report("gsub") do
N.times do
s = sample.dup
s = s.gsub(/x/, 'u')
end
end
end


09:41:57 [robert.klemme]: ruby /c/temp/ruby/stringperf.rb
user system total real
gsub! 3.203000 0.000000 3.203000 ( 3.242000)
gsub 3.203000 0.000000 3.203000 ( 3.250000)

Regards

robert

 

[Brian Schröder]

What new features would they provide?

Something I'm missing is to exclude certain statements and distinguish between
calls to the same method from different positions. If I profile any of my
progams I often get a result like

44.44 0.04 0.04 1 40.00 80.00 Array#each

where I'm using different Array#each's that I don't want to have mixed. (E.g.
for setup and then for the routine I want to profile.)

I could extract this cases into some extra class, but it would be nicer to tell
the profiler to discern between method call at line x and line y and not to
report method calls from line y.

Regards,

Brian

 

[Robert Klemme]

Something I'm missing is to exclude certain statements and distinguish between
calls to the same method from different positions. If I profile any of my
progams I often get a result like

44.44 0.04 0.04 1 40.00 80.00 Array#each

where I'm using different Array#each's that I don't want to have mixed. (E.g.
for setup and then for the routine I want to profile.)

I could extract this cases into some extra class, but it would be nicer to tell
the profiler to discern between method call at line x and line y and not to
report method calls from line y.

Although that's certainly desirable, I see these problems:

- the profiler does take away some performance already and I suspect this
feature would lead to even greater slowdown.

- usability of the profiler will degenerate, you'll have to configure the
profiler somehow and the nice and simple "-r 'profile'" will not suffice
any more (at least not for those cases where filtering / discrimination is
applied).

In the meantime you can use benchmark or Time which both are less
intrusive. Or you follow your approach to put the code you're interested
in into a special method / class.

Kind regards

robert

 

[Daniel Berger]

There's RbProf (from AspectR), though I don't know what it's status is these days.

Regards,

Dan

 

[Jamis Buck]

Slows down 58 times. Add something more then a siple counter to
trace_func and you get 100 times slowdown. I have a prototype for a
ruby profiler for ArachnoRuby that only slows down 30% and gives much
much more detailed measurements.

Are you going to leave us in suspense, then, or are you going to tell us
how we can get our hands on this profiler of yours? Or is it not
available outside of ArachnoRuby?

- Jamis

 

[Stephen Kellett]

Are you going to leave us in suspense, then, or are you going to tell
us how we can get our hands on this profiler of yours? Or is it not
available outside of ArachnoRuby?

Took me about 30 seconds to find it with Google.

http://www.ruby-ide.com/download_ruby.php

Stephen

 

[Jamis Buck]

Took me about 30 seconds to find it with Google.

http://www.ruby-ide.com/download_ruby.php

Clever, but I was looking for just the profiler, not the IDE. I was
curious as to whether the profiler was available separately.

- Jamis

 

[Glenn Parker]

Something I'm missing is to exclude certain statements and distinguish between
calls to the same method from different positions. If I profile any of my
progams I often get a result like

44.44 0.04 0.04 1 40.00 80.00 Array#each

where I'm using different Array#each's that I don't want to have mixed. (E.g.
for setup and then for the routine I want to profile.)

In Quantify, my profiler of choice from the C/C++ world (now part of
Rational PurifyPlus), you get access to a full overlapping call-graph
for every profiled function. You can find precise information about
exactly which functions call other functions, and how much time any
called function contributes to the calling functions total. Navigating
the mass of data in the Quantify GUI has point-and-click simplicity.

It's really quite nice, with a lot of information made easy to navigate.
Worth a look if you want ideas on how to improve a profiler.

Here's a link to some (slightly out-of-date) documentation that gives a
good overview:

http://bmrc.berkeley.edu/purify/docs/html/installing_and_gettingstarted/4-quantify.html

 

[gabriele renzi]

Jamis Buck ha scritto:

Clever, but I was looking for just the profiler, not the IDE. I was
curious as to whether the profiler was available separately.

IIRC there was a patch to ruby on the site from arachno ruby aimed at
speeding up debugging (maybe profiling too).
There is a little text about it on http://www.ruby-ide.com/ruby_faq.php
(I have the impression that it was downloadable but I may be wrong)

 

[Lothar Scholz]

Hello gabriele,

gr> Jamis Buck ha scritto:
gr> IIRC there was a patch to ruby on the site from argr> achno ruby aimed at
gr> speeding up debugging (maybe profiling too).

No profiling available at the moment. The idea is simple: just record
line number and pointer to the file name and the clock value in the C
code that calls the trace function before the binding is created
(which is the most expensive operation when executing the trace function).

This gathered data is then analysed later, when the buffer is full or
at end of the program.

The current pure ruby profiler tries to analyse the profiler data always
on the fly which reduces speed even more.

gr> There is a little text about it on
gr> http://www.ruby-ide.com/ruby_faq.php
gr> (I have the impression that it was downloadable but I may be wrong)

http://www.ruby-ide.com/downloads/diff-against-ruby-1.8.1.txt

 

[Stephen Kellett]

Clever, but I was looking for just the profiler, not the IDE. I was
curious as to whether the profiler was available separately.

I wasn't trying to be clever, and as I found out when I installed
ArachnoRuby, the help is non-existent and if there is a profiler with
it, I couldn't find it. Your mileage may vary...

Stephen

 

[Jonas Arvidsson]

I found the '-r profile' option. Are there any better tools out there?

Hello,

I felt the need for something that pinpoints which lines in
MY code are bottlenecks, so I wrote profstack.rb, which is a lot
slower than profile.rb, but presents the calling stack for each
entry in the list. Something I find useful.

Perhaps there's a smarter way to do this. Redefining Symbol#id2name
seems very costly, but at least I was able to modify the behavior
of profile.rb without modifying profile.rb.

Regards,
--Jonas

# Include stack trace in profile report.
# By requiring this file, you get profile reporting like this:
#
# % cumulative self self total
# time seconds seconds calls ms/call ms/call name
# 47.37 34.17 34.17 1 34173.00 64813.00 Range#each
# file.rb:141 each
# file.rb:141 process
# file.rb:328

require 'profile'

class Symbol
alias_method ld_id2name, :id2name

def id2name
stack = ""
c = caller()
if c.to_s =~ /profiler\.rb/ # Have we been called by the profiler?
c.each { |frame|
next if frame =~ /profiler\.rb/ # Skip internal profiler frames
stack += "\n" + (" " * 54) + frame.to_s.sub(/:in `(.*)'$/, ' \1')
}
end
old_id2name() + stack
end
end

 

[Jonas Arvidsson]

Hi,

In the "Class and Module Definitions" section of Chapter 19
in Pickaxe 1, there's code for a method called ExampleDate.once.
I've tried to generalize it in order to get return value
caching that works for any method - provided that the cached
method follows some rules:
- It must return a value based only on the values of the
arguments it receives.
- It can not have any side effects (such as changing some state
or doing any I/O operations).

You call cacheable or cacheable_singleton in the class where the
methods to cache are defined, a bit like private or attr_reader
and such. I put the "cacheable..." methods in Module at first,
but then they wouldn't work with methods on the outermost level.

What do you think? Is this technique fool-proof? Can it be
optimized? Any other comments?

I'm including an example of one case where caching works
beautifully. It's an implementation of the Fibonacci series using
recursion.

--Jonas

#---------------------- cacheable.rb ------------------------------
def cacheable_def(*ids)
ids.each { |id|
orig_method = cache = "__#{id.to_i}__"
yield <<-end_code
alias #{orig_method} #{id}

def #{id}(*args, &block)
def #{id}(*args, &block)
key = args.inspect + "\#{block}"
return @#{cache}[key] if @#{cache}.has_key? key
@#{cache}[key] = #{orig_method}(*args, &block)
end
@#{cache} = {}
self.#{id}(*args, &block)
end

END { puts "Cached \#{@#{cache}.size} values for #{id}" } if
$DEBUG
end_code
}
end

def cacheable(*ids)
cacheable_def(*ids) { |code| class_eval code }
end

def cacheable_singleton(*ids)
cacheable_def(*ids) { |code| instance_eval code }
end

#------------------------- fib.rb ------------------------------------
require 'benchmark'
require 'cacheable'

def fib(n)
n < 2 ? n : fib(n - 2) + fib(n - 1)
end

max = 30
results = []

Benchmark.bm(7) do |x|
x.report('normal:') { results << fib(max) }
cacheable_singleton :fib
x.report('cached:') { results << fib(max) }
end

p results