Let's Code a Basic Profiler

Paolo-_-Veñegas
Paolo Veñegas March 25, 2024

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!

Full source

profiler.rb