I'll close up my profiling trilogy with a little bit about profiling parts of your Ruby code. While ruby -r profile my_program or ruby-prof my_program are great for 90% of what you want to do, there's always the odd time that you really only care about one specific portion of your code — for example, if you're doing IO or setup tasks that you don't want to muddle your profile.
The Profiler__ library is the stock Ruby way of doing this, so let's look at this option first. Profiler__ has three methods that will be of interest to us:
- start_profile — which starts collecting data
- stop_profile — which stops data collection
- print_profile — which prints the collected data (it takes a parameter naming the filehandle to which it should print the data)
Say you had an rwb test script that looked like this (yes, I know I've depracated rwb, that doesn't mean I can't use it in a contrived little example):
urls = RWB::Builder.new()
tests = RWB::Runner.new(urls, 1000, 200)
Profiling this would be a nightmare, it relies on net/http and makes several gazillion calls to the Ruby Builtin and Standard Libraries — all these calls would dominate the run and resulting profile, the stuff you really care about (and can fix) would be buried. If I just wanted to profile the reporting functions, I could modify the test script to look like this:
require 'rwb' require 'profiler' urls = RWB::Builder.new() urls.add_url(10, "http://localhost") tests = RWB::Runner.new(urls, 1000, 200) tests.run Profiler__::start_profile tests.report_header tests.report_overall Profiler__::stop_profile Profiler__::print_profile($stderr)
This generates output like that below (edited to show the % time, cumulative seconds and name fields of the top twenty lines):
Which differs considerably from a profile of the entire script created with the -r profile command line option. The first twenty lines are shown here for comparison (edited as above):
% cumulative time seconds name 40.00 0.22 Array#each 20.00 0.33 Array#sort 18.18 0.43 Float#<=> 10.91 0.49 Array#push 3.64 0.51 Float#+ 3.64 0.53 Float#** 1.82 0.54 Float#- 1.82 0.55 RWB::Runner#report_heade 0.00 0.55 Float#to_f 0.00 0.55 RWB::Runner#results_mean 0.00 0.55 Math.sqrt 0.00 0.55 Class#new 0.00 0.55 Fixnum#/ 0.00 0.55 Array#shift 0.00 0.55 Array#initialize 0.00 0.55 Array# 0.00 0.55 Kernel.puts 0.00 0.55 Float#to_s 0.00 0.55 RWB::Runner#report_overa 0.00 0.55 Fixnum#+
(And yes, there is a rounding/floating point/addition error in the second example ... I know it's there, but haven't bothered to dig into the exact cause.)
% cumulative time seconds name 113.58 18.73 TCPSocket#initialize 92.06 33.91 Fixnum#== 7.52 35.15 Kernel.catch 7.16 36.33 RWB::Runner#run_test 7.03 37.49 RWB::Builder#get_url 6.61 38.58 URI.split 5.82 39.54 Net::HTTP#Proxy 5.34 40.42 Hash#include? 5.15 41.27 Kernel.block_given? 4.79 42.06 URI::HTTP#initialize 4.49 42.80 URI::Generic#find_proxy 4.37 43.52 Net::HTTP#new 4.12 44.20 Kernel.class 4.06 44.87 Kernel.open 3.88 45.51 URI::Generic#split_userinfo 3.82 46.14 OpenURI.open_loop 3.82 46.77 Net::HTTP#do_start 3.76 47.39 RWB::Result#initialize 3.40 47.95 Net::HTTP#initialize 3.09 48.46 RWB::Runner#run_thread 3.03 48.96 ENV.include?
One thing to watch out for is that Profiler__ will happily overwrite any existing profile data if Profiler__::start_profile gets called multiple times.
ruby-prof provides similar control over what gets profiled — actually, it provides more options. It uses the methods:
- start — starts a new profiling run
- stop — stops the current profiling run and returns the data
- profile — allows you to profile a block passed in to it
Printing is handled a bit differently though, Report objects are created, and then printed through a print method. Each kind of report has it's own Class:
- RubyProf::FlatPrinter — a traditional profiling report
- RubyProf::GraphPrinter — a call graph profiling report
- RubyProf::GraphHtmlPrinter — an html call graph profiling report
We can recreate the above example like this:
require 'rwb' require 'ruby-prof' urls = RWB::Builder.new() urls.add_url(10, "http://localhost") tests = RWB::Runner.new(urls, 1000, 200) tests.run RubyProf.start tests.report_header tests.report_overall result = RubyProf.stop printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT, 0)
Changing it to print a call graph just means changing the second to last line to this:
printer = RubyProf::GraphPrinter.new(result)
While these may not be the kinds of profiling tasks you do every day, it's nice to know that they're there.
If you found this post helpful, you might want to look at my ruby-prof post collection.