Profiling Your Application

Problem

You want to find the slowest parts of your application, and speed them up.

Solution

Include the Ruby profiler in your application with include profile and the profiler will start tracking and timing every subsequent method call. When the application exits, the profiler will print a report to your programs standard error stream.

Heres a program that contains a performance flaw:

	#!/usr/bin/env ruby
	# sequence_counter.rb
	require profile

	total = 0
	# Count the letter sequences containing an a, b, or c.
	(a..zz).each do |seq|
	 [a, , c].each do |i|
	 if seq.index(i)
	 total += 1
	 break
	 end
	 end
	end
	puts "Total: #{total}"

When the program is run, the profiler shows the parts of the program that are most important to optimize:

	$ ruby sequence_counter.rb
	Total: 150
	 % cumulative self self total
	 time seconds seconds calls ms/call ms/call name
	 54.55 0.30 0.30 702 0.43 0.50 Array#each
	 32.73 0.48 0.18 1 180.00 550.00 Range#each
	 7.27 0.52 0.04 1952 0.02 0.02 String#index
	 3.64 0.54 0.02 702 0.03 0.03 String#succ
	 1.82 0.55 0.01 150 0.07 0.07 Fixnum#+
	…

The program takes about 0.3 seconds to run, and most of that is spent in Array#each. What if we replaced that code with an equivalent regular expression?

	#!/usr/bin/env ruby
	# sequence_counter2.rb
	require profile

	total = 0
	# Count the letter sequences containing an a, b, or c.
	(a..zz).each {|seq| total +=1 if seq =~ /[abc]/ }
	puts "Total: #{total}"

Running this program yields a much better result:

	$ ruby sequence_counter2.rb
	Total: 150
	 % cumulative self self total
	 time seconds seconds calls ms/call ms/call name
	 83.33 0.05 0.05 1 50.00 60.00 Range#each
	 16.67 0.06 0.01 150 0.07 0.07 Fixnum#+
	 0.00 0.06 0.00 1 0.00 0.00 Fixnum#to_s
	…

The new version takes only 0.05 seconds to run, and as near as the profiler can measure, its running nearly as fast as an empty iterator over the range a..zz.

Discussion

You might think that regex_counter2.rb has a performance problem of its own. After all, it initializes the regular expression /[abc]/ within a loop, which seems to indicate that its being initialized multiple times. The natural instinct of the optimizing programmer is to move that definition outside the loop; surely that would be more efficient.

	re = /[abc]/
	(a..zz).each {|seq| total +=1 if seq =~ re }

But its not (try it!). The profiler actually shows a decrease in performance when the regular expression is assigned to a variable outside the loop. The Ruby interpreter is doing some optimization behind the scenes, and the code with an "obvious" performance problem beats the more complex "optimized" version.^[2] There is a general lesson here: the problem is often not where you think it is, and empirical data always beats guesswork.

^[2] Of course, a regular expression is a pretty simple object. If youve got a loop that builds a million-element data structure, or reads the same file over and over, the Ruby interpreter can help you. Move that sucker out of the loop. If you make this kind of mistake, itll show up in the profiler.

Rubys profiler is a fairly blunt tool (its written in only about 60 lines of Ruby), and to instrument it for anything but a simple command-line application, youll need to do some work. It helps if your code has unit tests, because profiler tests require a lot of the same scaffolding as unit tests. You can even build up a library of profiler test scripts to go with your unit tests, although the profiler output is difficult to analyze automatically.

If you know that some particular operation is slow, you can write code that stresstests that operation (the way you might write a unit test), and run only that code with the profiler. To stress-test sequence_counter2.rb, you might change it to operate on a larger range like (a..zzzz). Big datasets make performance problems more visible.

If you don know which operations are slow, pick the most common operations and instrument them on large datasets. If you e writing an XML library, write a profiler script that loads and parses an enormous file, and one that turns an enormous data structure into XML. If youve got no ideas at all, run the profiler on your unit test suite and look for problems. The tests that run slowly may be exercising problematic parts of your program.

The profiler results are ordered with the most time-consuming method calls first. To optimize your code, go from the top of the profiler results and address each call in turn. See why your script led to so many calls of that method, and what you can do about it. Either change the underlying code path so it doesn call that method so many times, or optimize the method itself. If the method is one you wrote, you can optimize it by profiling it in isolation.

The timing data given by the profiler isn terribly accurate,^[3] but it should be good enough to find problem areas. If you want a more reliable estimate of how long some code takes to run, try the benchmark library, or run your script using the Unix time command.

^[3] Note the timing inconsistencies in the examples above. Somehow the entire original sequence_counter.rb runs in 0.30 seconds, but when you ignore all the Array#each calls, the cumulative time jumps up to 0.48 seconds.

The Ruby profiler sets the interpreters trace function (by passing a code block into Kernel#set_trace_func), so if your program uses a trace function of its own, using the profiler will overwrite the old function. This probably won affect you, because the trace function is mainly used by profilers and other analysis tools.

See Also

If the profiler says your problem is in a commonly-called method like Array#each, you need to somehow figure out which calls to the method are the problematic ones; see Recipe 17.15, "Whos Calling That Method? A Call Graph Analyzer"