Let's Code a Basic Profiler
I was recently working on optimising some service classes as run times were getting longer with new changes. I needed to understand where the bottlenecks were, so I turned to profilers like the trusty rack-mini-profiler and ruby-prof. Both are great tools, but they can give very verbose results and are a bit tricky to configure for some use cases.
I got to thinking about how I would implement a simple tool to do what I needed, and it turned out to be a neat exercise that demonstrates Ruby’s object model and the flexibility offered by its core libraries.
Goals
A profiler can measure different aspects of code performance. For this exercise, the goal was to make a record of method calls on instances of the target classes, and measure the time each takes.
I wanted to be able to use my profiler on arbitrary code just like ruby-prof so I can use it from irb or the Rails console. I wanted it to target specific classes and track and measure calls to all methods, public or private. To keep things simple, class methods are not covered for now.
This is the interface I had in mind:
ruby
Profiler.watch(SomeService, AnotherService, YetAnotherService)
Profiler.profile { SomeService.new.call }
Implementation
I provide the full source at the end of this article, but let’s break it down from the top.
Essentially, I needed a way to track and time method calls. The brute force way would be to modify each target class and method to take measurements, but I wanted to declare targets and insert instrumentation dynamically. I implemented the profiler as a module and hooked into target classes with prepend. If this method is new to you, it mixes the given module’s instance methods into the class like include, but Ruby looks up the module’s methods before the class’ on invocation, so they effectively take precedence. You’ll see why this is useful later.
ruby
module Profiler
def self.watch(*targets)
targets.each do |target|
target.prepend(self)
end
end
def self.prepended(target)
target.instance_methods(false).each do |m|
wrap(m)
end
target.private_instance_methods(false).each do |m|
wrap(m, make_private: true)
end
end
end
The prepended class method is a hook that is called when a module is prepended to a class. In this hook, we call wrap on each of the target’s public and private methods, and this is where the measurement magic happens.
ruby
module Profiler
def self.wrap(method, make_private: false)
define_method m do |*args, **kwargs|
return_value = nil
invocation = [self.class, m, nil]
Profiler.record << invocation
elapsed = Benchmark.realtime { return_value = super(*args, **kwargs) }
invocation[-1] = elapsed
return_value
end
private m if make_private
end
def self.record
@@record ||= []
end
end
wrap defines a method with the same name as the original method. This new method calls the original one using super wrapped in Benchmark.realtime, makes a record of the time the invocation took, and returns the original method’s result. It needs to work with any parameter arity and type, so we use *args, **kwargs as a catch-all. It also makes the method private as needed, to match the original.
Since we prepended the module into the class, when the original method is called, Ruby finds our dynamically-defined method first and calls it instead of the original. This somewhat more elegant method of monkey patching allows us to modify behaviour without replacing the original code altogether.
Note that the invocation is recorded first, and then the resulting elapsed time is updated later. This ensures that the record matches the order in which methods are called. Profiler.record is just an accessor for the class variable @@record, ensuring it is initialised as an array.
Now let’s look at the entry point, Profiler.profile.
ruby
module Profiler
def self.profile
reset
invocation = [self, :profile, nil]
record << invocation
elapsed = Benchmark.realtime { yield if block_given? }
invocation[-1] = elapsed
record
end
def self.reset
@@record = []
end
end
The profile method takes a block and records the total time it takes to run, much like wrap does. It also does a reset so we start with an empty invocation record, and returns the record at the end.
And that’s all we need to gather basic profiling data! Let’s look at what this gives us so far.
Results
Now we can create a few dummy services and test the profiler.
ruby
class SomeService
def initialize
@another_service = AnotherService.new
end
def call
@another_service.call
end
end
class AnotherService
def initialize
@yet_another_service = YetAnotherService.new
end
def call
@yet_another_service.call
@yet_another_service.call
end
end
class YetAnotherService
def initialize
sleep 1
end
def call
some_private_method
end
private
def some_private_method
sleep 2
end
end
ruby
[1] pry(main)> Profiler.watch(SomeService, AnotherService, YetAnotherService)
[2] pry(main)> result = Profiler.profile { SomeService.new.call }
=> [[Profiler, :profile, 5.003275000024587],
[SomeService, :initialize, 1.0010710000060499],
[AnotherService, :initialize, 1.001064999960363],
[YetAnotherService, :initialize, 1.0010339999571443],
[SomeService, :call, 4.002175000030547],
[AnotherService, :call, 4.00216100004036],
[YetAnotherService, :call, 2.0010359999723732],
[YetAnotherService, :some_private_method, 2.0010229999898],
[YetAnotherService, :call, 2.001090999925509],
[YetAnotherService, :some_private_method, 2.001068999990821]]
Sweet, we now have a sequence of calls with rough elapsed times.
This will be a long list if we profile more complex code, so to wrap this up I’ve added a method to compile a summary, sorted by median time, grouped by target class, and printed in a neat table.
ruby
module Profiler
def self.summarise(result, sort_by: :median)
# Create a hash-of-hashes with default values
summary = Hash.new do |hash, key|
hash[key] = Hash.new { |h, v| h[v] = [] }
end
# Group elapsed times by target class and method
result.each do |target, m, elapsed|
summary[target][m] << elapsed
end
# Summarise each method's invocations and sort per target class
summary.transform_values! do |methods|
methods.map do |m, invocations|
{
method: m,
median: median(invocations).round(2),
total: invocations.sum.round(2),
count: invocations.length
}
end.sort { |a, b| b[sort_by] <=> a[sort_by] }
end
# Implementation in full source
print_table(summary)
summary
end
end
Summarised output:
[3] pry(main)> Profiler.summarise(result)
method median total count
------------------------------------------------------------
Profiler profile 5.0 5.0 1
SomeService call 4.0 4.0 1
initialize 1.0 1.0 1
AnotherService call 4.0 4.0 1
initialize 1.0 1.0 1
YetAnotherService call 2.0 4.0 2
some_private_method 2.0 4.0 2
initialize 1.0 1.0 1
=> {Profiler=>[{:method=>:profile, :median=>5.0, :total=>5.0, :count=>1}],
SomeService=>
[{:method=>:call, :median=>4.0, :total=>4.0, :count=>1},
{:method=>:initialize, :median=>1.0, :total=>1.0, :count=>1}],
AnotherService=>
[{:method=>:call, :median=>4.0, :total=>4.0, :count=>1},
{:method=>:initialize, :median=>1.0, :total=>1.0, :count=>1}],
YetAnotherService=>
[{:method=>:call, :median=>2.0, :total=>4.0, :count=>2},
{:method=>:some_private_method, :median=>2.0, :total=>4.0, :count=>2},
{:method=>:initialize, :median=>1.0, :total=>1.0, :count=>1}]}
And there you have it, a basic profiler in a hundred-odd lines. While nowhere near a full-fledged profiler in terms of features and speed (not to mention thread safety), this tool can give good insights into code performance and help identify areas for optimisation, and we got to explore some clever language features to implement it. Ruby’s unique ability to introspect code in runtime and dynamically modify it with mixins and tools like define_method makes the language incredibly flexible and powerful. Of course, this power comes with commensurate responsibility, and it should be stressed that these features should be used sparingly and carefully, especially in production.
Until next time, and happy hacking!
