Imagine you're managing a busy professional kitchen during the Friday night rush. The customers are complaining that their food is taking too long to arrive. Now, you could just yell at everyone to "work faster," but that's a waste of energy. You don't actually know why it's slow. Is the prep cook taking forever to chop the onions? Is the grill chef struggling with the steaks? Or is the plating station the actual bottleneck where everything piles up?

To fix this, you wouldn't guess. You'd stand there with a stopwatch and time exactly how long a dish spends at each station. That's exactly what profiling is in Ruby. Instead of guessing that a specific loop is "probably the slow part," we use a profiler to tell us exactly how many milliseconds were spent in each method.

In the Ruby world, ruby-prof is the stopwatch of choice. It doesn't just tell you the total runtime of your script; it breaks down the execution into a call graph, showing you which methods are the "bottlenecks" and which ones are just passengers.

Getting ruby-prof into your project

First, you'll need the gem. I usually add this to my :development group in the Gemfile because you definitely don't want the profiling overhead running in production. It would slow your app to a crawl.

gem install ruby-prof

Wrapping your code for measurement

You don't want to profile your entire boot process (like loading Rails or your gems), because that will clutter your report with noise. Instead, you wrap only the specific block of code you suspect is lagging. Let's look at a real-world scenario: a report generator that calculates user spending habits. I've written this one intentionally poorly to give us something to find.

require 'ruby-prof'

class SpendingReport
  def initialize(users)
    @users = users
  end

  def generate
    @users.map do |user|
      # This is a hidden performance killer
      calculate_total_spend(user)
    end
  end

  def calculate_total_spend(user)
    # Simulating a slow operation, like an inefficient DB query
    sleep(0.01) 
    user[:transactions].sum { |t| t[:amount] }
  end
end

# Setup some dummy data
users = Array.new(100) { { name: "User", transactions: [{amount: 10}, {amount: 20}] } }
report = SpendingReport.new(users)

# Here is the profiling magic
RubyProf.start

report.generate

result = RubyProf.stop

Deciphering the Wall Time

Once you've stopped the profiler, you have a result object, but it's not human-readable yet. You need a printer. I almost always use the FlatPrinter for a quick sanity check, as it gives you a straightforward list of where the time went.

printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

When you look at the output, you'll see columns like Self and Total. This is where most people get confused. Pay close attention: Self time is the time spent exclusively inside that method. Total time is the time spent in that method plus all the other methods it called. If generate has a high total time but a low self time, it means the slowness isn't in the loop itself, but in the method the loop is calling (in our case, calculate_total_spend).

Visualizing the Call Stack

If your app is complex, a flat list isn't enough. You need to see the "who called whom" relationship. For this, I use the GraphPrinter, which generates a .dot file you can view as an image. It's a bit more setup, but it's the only way to spot deep architectural bottlenecks.

printer = RubyProf::GraphPrinter.new(result)
printer.print(File.open("profile_graph.dot", "w"))

I've spent hours staring at code thinking a specific regex was the problem, only to run a profile and realize the app was spending 90% of its time in a logger that I had forgotten to turn off. Don't trust your gut; trust the profiler.

📋 Practical Task

Optimizing the Slow Portfolio Aggregator

You've been handed a script that aggregates stock portfolios for a group of clients. The current implementation is painfully slow. Your goal is to use ruby-prof to identify the exact method causing the bottleneck and then refactor it to improve performance.

The Scenario:
The PortfolioManager class iterates through a list of portfolios. Inside, it calls a method fetch_current_price. Currently, this method is simulating a network request using sleep(0.05) for every single single asset in every single portfolio. This is an "N+1" style performance disaster.

# portfolio_aggregator.rb
require 'ruby-prof'

class PortfolioManager
  def initialize(portfolios)
    @portfolios = portfolios
  end

  def total_value_report
    @portfolios.map do |portfolio|
      portfolio_sum(portfolio)
    end
  end

  def portfolio_sum(portfolio)
    portfolio[:assets].sum do |asset|
      fetch_current_price(asset) * asset[:quantity]
    end
  end

  def fetch_current_price(asset)
    sleep(0.05) # Simulating a slow API call
    100.0
  end
end

# Setup: 20 portfolios with 10 assets each
data = Array.new(20) { { assets: Array.new(10) { { name: "Stock", quantity: 5 } } } }
manager = PortfolioManager.new(data)

RubyProf.start
manager.total_value_report
result = RubyProf.stop

printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

Your Task:

1. Run the code as provided. Identify the method with the highest Self Time in the output.
2. Refactor the PortfolioManager to reduce the number of calls to fetch_current_price. (Hint: Think about "bulk fetching" or caching the price of the asset so you don't sleep for every single item).
3. Run the profiler again and verify that the Total Time for the total_value_report method has dropped significantly.