When reading the official Ruby 3.0 release post, one bullet caught my eye especially. With Ruby 3.0, IRB introduced a measure command. As someone who often times little snippets when debugging, comparing code, or writing new code, I was intrigued! IRB’s new measure command is a quick and easy way to measure different snippets from an IRB console.

Toggling measure

As the release notes demonstrated, we can toggle measure on by using measure (or measure :on), and off by using measure :off

irb(main)> measure
TIME is added
=> nil

irb > sleep 1
processing time: 1.000649s
=> 1

irb > 1
processing time: 0.000025s
=> 1

irb > measure :off
=> nil

By default, as we can see above, the IRB console will print out the processing time in seconds (the time measurement) for all commands when measure is toggled on.

Stackprof

When I was reading the release notes, the message of TIME is added caught my eye because it implies that there are other ways we can measure code with this new command! It turns out measure comes with one more default mode: Stackprof.

Stackprof (short for Stack Profiler) is a sampling call stack profiler for Ruby code. This means that it will take many samples while code is running of where in the stack the execution is happening, and be able to give us an estimate of how much time we are spending in each step of a call stack. We can toggle measuring Stackprof with measure :stackprof.

Before demonstrating Stackprof functionality, we’ll need a code snippet which does a little more than print out an integer to really see what’s happening. And ideally we’ll run it a few (or few thousand) times. Let’s celebrate the fact that it’s no longer 2020 (and that Ruby 3 also introduced endless method definition), and use this snippet:

def snippet()= 10_000.times { Date.parse(Date.today.to_s).year != 2020 }

Now, we can run the snippet with Stackprof and see the following output:

irb > measure :stackprof
STACKPROF is added.
=> nil

irb > snippet
==================================
  Mode: cpu(1000)
  Samples: 26 (0.00% miss rate)
  GC: 2 (7.69%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
        11  (42.3%)          11  (42.3%)     Regexp#match
         5  (19.2%)           5  (19.2%)     String#gsub!
         4  (15.4%)           4  (15.4%)     Integer#div
         2   (7.7%)           2   (7.7%)     MatchData#begin
         2   (7.7%)           2   (7.7%)     (sweeping)
         1   (3.8%)           1   (3.8%)     Date.today
         1   (3.8%)           1   (3.8%)     Date#to_s
        24  (92.3%)           0   (0.0%)     IRB::WorkSpace#evaluate
        24  (92.3%)           0   (0.0%)     IRB::Irb#eval_input
        24  (92.3%)           0   (0.0%)     IRB.init_config
        24  (92.3%)           0   (0.0%)     StackProf.run
        24  (92.3%)           0   (0.0%)     IRB::Irb#signal_status
        24  (92.3%)           0   (0.0%)     RubyLex#each_top_level_statement
        24  (92.3%)           0   (0.0%)     Kernel#loop
        24  (92.3%)           0   (0.0%)     Kernel#catch
        24  (92.3%)           0   (0.0%)     IRB::Irb#run
        24  (92.3%)           0   (0.0%)     IRB.start
        24  (92.3%)           0   (0.0%)     <top (required)>
        24  (92.3%)           0   (0.0%)     Kernel#load
        24  (92.3%)           0   (0.0%)     <main>
        24  (92.3%)           0   (0.0%)     <main>
        24  (92.3%)           0   (0.0%)     Kernel#eval
        24  (92.3%)           0   (0.0%)     <main>
         2   (7.7%)           0   (0.0%)     (garbage collection)
        24  (92.3%)           0   (0.0%)     Integer#times
        24  (92.3%)           0   (0.0%)     Object#snippet
        22  (84.6%)           0   (0.0%)     Date.parse
        24  (92.3%)           0   (0.0%)     IRB::Context#evaluate
=> 10000

Huzzah! We’re getting a Stackprof report from an IRB console with absolutely no custom code!

To further explain the output, we’re seeing how many samples were taken at each stack frame and what percentage of time that amounts to. For instance, the first tells us that there were 11 samples taken at the Regexp#match frame. The header at the top tells us there were 26 total samples taken. So Stackprof is extrapolating here that 11/26, or 42.3%, of our time is spent in Regexp#match. This 42.3% is represented in the (pct) column. In this way, the Stackprof output gives us an accurate estimate of how much time different stack frames are taking in the execution of our code.

We can also see in the header that this is profiling in cpu mode. This means Stackprof will take samples every millisecond of time where there is cpu activity. But, Stackprof has many more sampling modes! One other interesting one is wall sampling, which takes samples every millisecond of actual time, regardless of if there is cpu activity or not.

The built-in measure :stackprof actually allows us to pass an argument, which is the mode for which we want to run Stackprof. For instance, to use wall time sampling, we can run:

irb > measure :stackprof, :wall
STACKPROF is added.
=> nil

irb > snippet
==================================
  Mode: wall(1000)
  Samples: 56 (0.00% miss rate)
  GC: 5 (8.93%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
        20  (35.7%)          20  (35.7%)     Regexp#match
        10  (17.9%)          10  (17.9%)     Date.today
...
...
=> 10000

We can get both time and stackprof measurements by simply toggling them both. Note that we can also set the measurement explicitly to time by using measure :time. They’ll print in the order in which we add them:

irb > measure :time
TIME is added.
=> nil

irb > measure :stackprof
STACKPROF is added.
processing time: 0.000165s
=> nil

irb > snippet
processing time: 0.058907s
==================================
  Mode: cpu(1000)
  Samples: 35 (0.00% miss rate)
  GC: 5 (14.29%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
         7  (20.0%)           7  (20.0%)     Regexp#match
         6  (17.1%)           6  (17.1%)     Date.today
...
...
=> 10000

To see which measurements we’re currently taking, we can use measure :list. Note that it’ll still also output the measurements (processing time and Stackprof output, in our case) from running measure :list:

irb > measure :list
- TIME
- STACKPROF
processing time: 0.000129s
==================================
  Mode: cpu(1000)
  Samples: 0 (NaN% miss rate)
  GC: 0 (NaN%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
=> nil

Custom measure procedures

Right about now, you might be thinking, “This is neat, but what if we want our own measure procedure?” You also might be thinking, “Wow, what a fun blog post!”

In either case, we’re just getting started! Check out the second part of this blog post to learn more about writing custom measure procedures.

TL;DR

In summary, here is what we learned about IRB’s new measure functionality

  • measure will toggle measurement on, defaulting to measuring time of commands
  • measure :off toggles measurement off
  • measure :stackprof is built-in, and outputs Stackprof (default mode: cpu) results of code
  • measure :list lists all measurement modes currently in use
  • And there’s more about custom measure procedures