Multipart Profiling (and a Rails Profiling Hint)

In a comment on my Profiling and ruby-prof: Getting Specific post, Thorsten asked:

If you profile just a part of your code, is it possible to accumulate over multiple "parts"? For example, I want to profile a Rails action invocation, but I really want to profile 100 invocations. So I want to start/stop the profiling 100 times just around the action invocation and at the end I want to print out a single profile (not 100). Can this be done?

Instead of answering him there, I thought it would be worth devoting a post to the answer, not because it's hard to answer but so that the answer doesn't get lost. (And maybe to help people see how to find things like this for themselves.

Let's start with a little code sample:

require 'profiler'

Profiler__::start_profile
puts "profiling"
ary = (1..10).to_a
puts ary.join(" ")
Profiler__::stop_profile
Profiler__::print_profile($stderr)

Running this generates output like so:

profiling
1 2 3 4 5 6 7 8 9 10
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
100.00     0.01      0.01        1    10.00    10.00  Array#join
  0.00     0.01      0.00        1     0.00     0.00  Enumerable.to_a
  0.00     0.01      0.00        4     0.00     0.00  IO#write
  0.00     0.01      0.00        1     0.00     0.00  Range#each
  0.00     0.01      0.00       10     0.00     0.00  Fixnum#to_s
  0.00     0.01      0.00        2     0.00     0.00  Kernel.puts
  0.00     0.01      0.00        1     0.00    10.00  #toplevel

Now, let's change the code so that we're profiling two different things:

require 'profiler'

Profiler__::start_profile
puts "profiling"
ary = (1..10).to_a
puts ary.join(" ")
Profiler__::stop_profile

puts "not profiling"

Profiler__::start_profile
puts "profiling again"
1.upto(100) { |i| i += 1 }
Profiler__::stop_profile

puts "back out of profiling"
Profiler__::print_profile($stderr)

Which generates:

profiling
1 2 3 4 5 6 7 8 9 10
not profiling
profiling again
back out of profiling
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
100.00     0.01      0.01        1    10.00    10.00  Integer#upto
  0.00     0.01      0.00        1     0.00     0.00  Kernel.puts
  0.00     0.01      0.00        2     0.00     0.00  IO#write
  0.00     0.01      0.00      100     0.00     0.00  Fixnum#+
  0.00     0.01      0.00        1     0.00    10.00  #toplevel

Okay, so the first bunch of profiling data got stomped on. That answers Thorstens question. But maybe not the question he meant to ask. If he's trying to benchmark his code to see how fast it is, the Benchmark library is a much better choice than Profile, Profiler__, and ruby-prof (but not a perfect answer either ... hmm, that seems like another blog post I need to write). If he wants to analyze Rails stuff and not worry about the Ruby code itself, he might want to look at Rails Analyzer by Eric Hodel (and especially at Action Profiler).

If you found this post helpful, you might want to look at my ruby-prof post collection.