Seattle.rb: May 2009 Archives

zenprofiler helps answer WHAT is being called the most. spyon helps answer WHERE those calls are being made. ZenProfiler provides a faster version of the standard library ruby profiler. It is otherwise pretty much the same as before. spyon provides a clean way to redefine a bottleneck method so you can account for and aggregate all the calls to it.

% ruby -Ilib bin/zenprofile misc/factorial.rb 50000
Total time = 3.056884
Total time = 2.390000

          total     self              self    total
% time  seconds  seconds    calls  ms/call  ms/call  name
 50.70     1.64     1.64    50000     0.03     0.05 Integer#downto
 19.63     2.27     0.63   200000     0.00     0.00 Fixnum#*
 14.19     2.73     0.46    50000     0.01     0.05 Factorial#factorial
  9.93     3.05     0.32        1   320.36  3047.10 Range#each
  5.54     3.23     0.18        2    89.40   178.79 ZenProfiler#start_hook

Once you know that Integer#downto takes 50% of the entire run, you can use spy_on to find it. (See misc/factorial.rb for the actual code):

% SPY=1 ruby -Ilib misc/factorial.rb 50000
Spying on Integer#downto

Integer.downto

50000: total
50000: ./misc/factorial.rb:6:in `factorial' via 
       ./misc/factorial.rb:6:in `factorial'

Changes:

1.0.0 / 2008-09-17

• 1 major enhancement

  • Birthday!

• http://rubyforge.org/projects/seattlerb

Wraps rbaddeventhook so you can write fast ruby event hook processors w/o the speed penalty that comes with settrace_func (sooo sloooow!). Calls back into ruby so you don't have to write C.

% ruby demo.rb 
# of iterations = 1000000
                          user     system      total        real
null_time             0.120000   0.000000   0.120000 (  0.125279)
ruby time             0.560000   0.000000   0.560000 (  0.562834)
event hook            3.160000   0.010000   3.170000 (  3.175361)
set_trace_func       34.530000   0.100000  34.630000 ( 34.942785)

Changes:

1.0.0 / 2009-05-19

• 1 major enhancement

  • Birthday!

• http://rubyforge.org/projects/seattlerb