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 wrote:
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?
zach
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
···
On Wed, 1 Dec 2004 06:52:47 +0900 "Joe Van Dyk" <joe.vandyk@boeing.com> wrote:
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
--
Brian Schröder
http://www.brian-schroeder.de/
Joe Van Dyk wrote:
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?
Joe Van Dyk wrote:
I found the '-r profile' option. Are there any better tools out there?
What new features would they provide?
"Brian Schröder" <ruby@brian-schroeder.de> schrieb im Newsbeitrag
news:20041130230416.6299104d@black.wg...
> 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
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
···
On Wed, 1 Dec 2004 06:52:47 +0900 > "Joe Van Dyk" <joe.vandyk@boeing.com> wrote:
Joe Van Dyk wrote:
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,
JoeI 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 :old_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
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
···
On Wed, 1 Dec 2004 08:12:52 +0900 Florian Gross <flgr@ccan.de> wrote:
Joe Van Dyk wrote:
> I found the '-r profile' option. Are there any better tools out there?
What new features would they provide?
--
Brian Schröder
http://www.brian-schroeder.de/
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
"Brian Schröder" <ruby@brian-schroeder.de> schrieb im Newsbeitrag
news:20041201121041.6a44a927@black.wg...
> Joe Van Dyk wrote:
>
> > I found the '-r profile' option. Are there any better tools out
there?
>
> 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.
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
···
On Wed, 1 Dec 2004 08:12:52 +0900 > Florian Gross <flgr@ccan.de> wrote:
Brian Schröder wrote:
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 like44.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
···
--
Glenn Parker | glenn.parker-AT-comcast.net | <http://www.tetrafoil.com/>
Hello Robert,
"Brian Schröder" <ruby@brian-schroeder.de> schrieb im Newsbeitrag
news:20041201121041.6a44a927@black.wg...> Joe Van Dyk wrote:
>
> > I found the '-r profile' option. Are there any better tools outthere?
>
> 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.
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.
Even at the moment the profiler is at a proof of concept level and absolute
unusable in programs that do a little bit more then "puts 'hello
world'". It slows down a program by at least a factor 50.
Every solution that is based on "set_trace_func" is in my opinion just
rubbish. try this with an empty proc and see how it slows down the
program and you will understand.
···
On Wed, 1 Dec 2004 08:12:52 +0900 >> Florian Gross <flgr@ccan.de> wrote:
-----------------------------------
require "rexml/document"
$a = 0
set_trace_func proc { |event, file, line, id, binding, klass, *rest|
$a += 1
}
a = Time.new
doc = REXML::Document.new File.new( "z:/work/eiffel/agui/build.eant" )
b = Time.new
print "Time : " , b - a, "\n"
print "Calls : " , $a, "\n"
-----------------------------------
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.
--
Best regards, emailto: scholz at scriptolutions dot com
Lothar Scholz http://www.ruby-ide.com
CTO Scriptolutions Ruby, PHP, Python IDE 's
"Robert Klemme" <bob.news@gmx.net> wrote in message news:<315o70F37s1jeU1@individual.net>...
"Brian Schröder" <ruby@brian-schroeder.de> schrieb im Newsbeitrag
news:20041201121041.6a44a927@black.wg...
>
> > Joe Van Dyk wrote:
> >
> > > I found the '-r profile' option. Are there any better tools out
there?
> >
> > What new features would they provide?
There's RbProf (from AspectR), though I don't know what it's status is these days.
Regards,
Dan
···
> On Wed, 1 Dec 2004 08:12:52 +0900 > > Florian Gross <flgr@ccan.de> wrote:
"Lothar Scholz" <mailinglists@scriptolutions.com> schrieb im Newsbeitrag
news:13616401843.20041201132350@scriptolutions.com...
> - the profiler does take away some performance already and I
suspect this
> feature would lead to even greater slowdown.
Even at the moment the profiler is at a proof of concept level and
absolute
unusable in programs that do a little bit more then "puts 'hello
world'". It slows down a program by at least a factor 50.Every solution that is based on "set_trace_func" is in my opinion just
rubbish. try this with an empty proc and see how it slows down the
program and you will understand.
I *have* in fact used the profiler already. I would not go so far as to
call it "rubbish". It has its use although I'd readily admit that it's
limited. But it's not rubbish. Java's hprof with cpu=times has similar
bad impacts on overall performance but it is useful in certain situations.
(I admit though that I use cpu=samples most of the time :-))
Kind regards
robert
Lothar Scholz wrote:
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
···
--
Jamis Buck
jgb3@email.byu.edu
http://www.jamisbuck.org/jamis
Took me about 30 seconds to find it with Google.
http://www.ruby-ide.com/download_ruby.php
Stephen
···
In message <41ADDA1C.9090300@byu.edu>, Jamis Buck <jamis_buck@byu.edu> writes
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?
--
Stephen Kellett
Object Media Limited http://www.objmedia.demon.co.uk
RSI Information: http://www.objmedia.demon.co.uk/rsi.html
A little while back I told someone who was looking to speed up a Ruby script to run it with the profiler.... they thought the profiler was broken, because it took so long
A 10 second script turned into 5-10 minutes. But in the end it did work and helped us tune the program and get some very significant speed ups... which is what matters.
On a side note, in my experience object creation and garbage collection (something that isn't really measured by the profiler) seems to have the biggest impact on speed. If you can reduce the number of objects created, the GC spends less time marking and sweeping objects.
-Charlie
···
On Dec 1, 2004, at 4:52 AM, Robert Klemme wrote:
"Lothar Scholz" <mailinglists@scriptolutions.com> schrieb im Newsbeitrag
news:13616401843.20041201132350@scriptolutions.com...> - the profiler does take away some performance already and I
suspect this
> feature would lead to even greater slowdown.
Even at the moment the profiler is at a proof of concept level and
absolute
unusable in programs that do a little bit more then "puts 'hello
world'". It slows down a program by at least a factor 50.Every solution that is based on "set_trace_func" is in my opinion just
rubbish. try this with an empty proc and see how it slows down the
program and you will understand.I *have* in fact used the profiler already. I would not go so far as to
call it "rubbish". It has its use although I'd readily admit that it's
limited. But it's not rubbish. Java's hprof with cpu=times has similar
bad impacts on overall performance but it is useful in certain situations.
(I admit though that I use cpu=samples most of the time :-))
Stephen Kellett wrote:
···
In message <41ADDA1C.9090300@byu.edu>, Jamis Buck <jamis_buck@byu.edu> > writes
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?
Took me about 30 seconds to find it with Google.
Clever, but I was looking for just the profiler, not the IDE. I was curious as to whether the profiler was available separately.
- Jamis
--
Jamis Buck
jgb3@email.byu.edu
http://www.jamisbuck.org/jamis
"Charles Mills" <cmills@freeshell.org> schrieb im Newsbeitrag
news:E23078B9-43AF-11D9-AA47-000A95A27A10@freeshell.org...
>
> "Lothar Scholz" <mailinglists@scriptolutions.com> schrieb im
> Newsbeitrag
> news:13616401843.20041201132350@scriptolutions.com...
>
>> > - the profiler does take away some performance already and I
> suspect this
>> > feature would lead to even greater slowdown.
>>
>> Even at the moment the profiler is at a proof of concept level and
> absolute
>> unusable in programs that do a little bit more then "puts 'hello
>> world'". It slows down a program by at least a factor 50.
>>
>> Every solution that is based on "set_trace_func" is in my opinion
just
>> rubbish. try this with an empty proc and see how it slows down the
>> program and you will understand.
>
> I *have* in fact used the profiler already. I would not go so far as
> to
> call it "rubbish". It has its use although I'd readily admit that
it's
> limited. But it's not rubbish. Java's hprof with cpu=times has
> similar
> bad impacts on overall performance but it is useful in certain
> situations.
> (I admit though that I use cpu=samples most of the time :-))
>
A little while back I told someone who was looking to speed up a Ruby
script to run it with the profiler.... they thought the profiler was
broken, because it took so long
If you have suspects and the profiler slows down too much, you can even
time manually with a helper method like this:
module Kernel
private
def time(msg)
t = Time.now.to_f
begin
return yield
ensure
t = Time.now.to_f - t
$stderr.puts "#{msg} took #{t} sec"
end
end
end
time("print 100 x") { 100.times { print "x" } ; puts }
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxxxxxxxxxxxxxxxxxxxxxxxxx
print 100 x took 0.00399994850158691 sec
=> nil
A 10 second script turned into 5-10 minutes. But in the end it did
work and helped us tune the program and get some very significant speed
ups... which is what matters.
!
On a side note, in my experience object creation and garbage collection
(something that isn't really measured by the profiler) seems to have
the biggest impact on speed. If you can reduce the number of objects
created, the GC spends less time marking and sweeping objects.
Yeah, it's the same with Java.
Kind regards
robert
···
On Dec 1, 2004, at 4:52 AM, Robert Klemme wrote:
Robert Klemme schrieb:
"Charles Mills" <cmills@freeshell.org> schrieb im Newsbeitrag
news:E23078B9-43AF-11D9-AA47-000A95A27A10@freeshell.org..."Lothar Scholz" <mailinglists@scriptolutions.com> schrieb im
Newsbeitrag
news:13616401843.20041201132350@scriptolutions.com...- the profiler does take away some performance already and I
suspect this
feature would lead to even greater slowdown.
Even at the moment the profiler is at a proof of concept level and
absolute
unusable in programs that do a little bit more then "puts 'hello
world'". It slows down a program by at least a factor 50.Every solution that is based on "set_trace_func" is in my opinion
just
rubbish. try this with an empty proc and see how it slows down the
program and you will understand.I *have* in fact used the profiler already. I would not go so far as
to
call it "rubbish". It has its use although I'd readily admit thatit's
limited. But it's not rubbish. Java's hprof with cpu=times has
similar
bad impacts on overall performance but it is useful in certain
situations.
(I admit though that I use cpu=samples most of the time :-))A little while back I told someone who was looking to speed up a Ruby
script to run it with the profiler.... they thought the profiler was
broken, because it took so longIf you have suspects and the profiler slows down too much, you can even
time manually with a helper method like this:module Kernel
private
def time(msg)
t = Time.now.to_f
begin
return yield
ensure
t = Time.now.to_f - t
$stderr.puts "#{msg} took #{t} sec"
end
end
end
Or just use 'benchmark' (sorry, I've currently no Ruby reference here, look up ri Benchmark or lib/benchmark.rb for reference).
Regards,
Michael
···
On Dec 1, 2004, at 4:52 AM, Robert Klemme wrote: