IRB's Built-in Measure
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
measurewill toggle measurement on, defaulting to measuring time of commandsmeasure :offtoggles measurement offmeasure :stackprofis built-in, and outputs Stackprof (default mode: cpu) results of codemeasure :listlists all measurement modes currently in use- And there’s more about custom measure procedures