Profiling: the obvious step after Benchmarking your Ruby code.

Weeks ago I wrote a post about Benchmarking your Ruby code. I talked about how doing it would improve your coding skills and make you a better programmer.

It also contained a straight forward tutorial on how to do it. If you didn't catch the time to read it or somehow you missed it, here is the LINK - "How Benchmarking Your Code Will Improve Your Ruby Skills".

Knowledge is power

To bring back some of those ideas. I commented that knowledge is power, and Benchmarking gives you exactly that.

The power to choose the best and most optimal solution, to a specific problem.

In other words... Benchmarking lets you compare two or more alternative solutions in three main areas:

The result you'll get will give you enough information to choose one solution over the other.

This is great! isn't it? Being confident to say why one option is better than others.

But the thing doesn't end there. The next question to ask is...

Could this solution be improved?

By now, we already know our chosen solution is the most optimal among others. And here is where Profiling comes handy.

What's profiling?

Profiling is a method, that helps you get inside your code. It lets you identify potential problems and bottlenecks.

So, what's the difference vs benchmarking?

Benchmarking and profiling, are both related to performance. The difference is in the things they compare and analyze.

While benchmarking compares two or more solutions. Profiling tells you about the steps and the time a specific solution spends in each one of them while solving the problem.

This will be better explained in a practical exercise. Don't worry.

How to profile your code?

Profiling your code is easy as benchmarking, there are a lot of gems related to this topic, but Ruby also has its Profile built-in library.

And the steps for using it are very simple:

ruby -rprofile file_to_profile.rb

If you noticed, there is nothing complicated about it. The only difference is this

-rprofile

Let's see a quick example of the output from our exercise file: file_to_profile.rb

a) Content of file_to_profile.rb

# file_to_profile.rb

# Medoths available
def one_1
  1
end

def two_2
  one + one
end

def three_3
  two + one
end

# calls method three_3
three_3

b) Run the command

ruby -rprofile file_to_profile.rb

c) Observe the output

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 34.23     0.00      0.00        1     1.10     1.10  Profiler__.start_profile
  1.15     0.00      0.00        1     0.04     0.05  Object#two
  1.02     0.00      0.00        1     0.03     0.09  Object#three
  0.56     0.00      0.00        2     0.01     0.01  IO#set_encoding
  0.50     0.00      0.00        3     0.01     0.01  Module#method_added
  0.31     0.00      0.00        3     0.00     0.00  Object#one
  0.25     0.00      0.00        2     0.00     0.00  Integer#+
  0.16     0.00      0.00        1     0.00     0.00  Kernel#respond_to?
  0.12     0.00      0.00        1     0.00     0.00  Monitor#mon_owned?
  0.00     0.00      0.00        1     0.00     3.23  #toplevel

The most important parts of the output are these columns:

% time

calls 

name

1.

% time

2.

calls

E.g. if we profile an

each

n

3.

name

It looks interesting... but the output is not making any sense... What does that tell me?

As I said knowledge is power, and profile expands that power even more. I have to admit that as a beginner this profile output doesn't make any sense at first look.

Now, let's try to apply it and analyze the output.

BE AWARE: this is a tutorial for beginners, to give an idea of how profiling will help them improve. There are more topics related and more to understand about profiling. I'm scratching the surface in hopes this will motivate others to dive deeper into the subject.

Example

I'll be using the same example I use in "How Benchmarking Your Code Will Improve Your Ruby Skills". This is the summary:

You were selected to solve a coding challenge. The instructions were.

Constraints:

• The collection doesn't skip numbers.
• The elements are sorted.
• Goes from 1 to

  n.

• They increase 1 value at a time: 1, 2, 3, ...

The solution you choose after benchmarking it was this one:

def sum_3(arr)
  arr.sum
end

This solution was the most efficient approach of all.

Our file looks for the exercise looks like this:

file_to_profile.rb

# Our method to profile
def sum_3(arr)
  arr.sum
end

# An array for the example
arr = [*(1..1000)] # This creates an array that goes from 1 to 1_000

# The call to our method
sum_3(arr)

With our file and method ready we run the profiler.

ruby -rprofile file_to_profile.rb

The output:

 time   seconds   seconds    calls  ms/call  ms/call  name
 37.28     0.00      0.00        1     0.87     0.87  Profiler__.start_profile
  0.43     0.00      0.00        2     0.00     0.00  IO#set_encoding
  0.34     0.00      0.00        1     0.01     0.01  Object#sum_3
  0.21     0.00      0.00        1     0.00     0.00  Module#method_added
  0.13     0.00      0.00        1     0.00     0.00  Kernel#respond_to?
  0.13     0.00      0.00        1     0.00     0.00  Monitor#mon_owned?
  0.13     0.00      0.00        1     0.00     0.00  Array#sum
  0.00     0.00      0.00        1     0.00     2.33  #toplevel

A) First of all, let's go through the table and focus on the "name" column (the last one).

This column gives us information about the classes and the methods our sum_3 method is using.

Let's analyze the information from top to bottom. Identify the ones that are related, and discard the unnecessary ones.

1. Profiler__.start_profile # This is the one that lets the magic happens, is the one that starts the Ruby profiler.
2. IO#set_encoding # not important for our purpose. More info.
3. Object#sum_3 # This one is telling us we have an object call sum_3. This is related completely to our code. Is our method itself.
4. Module#method_added # not important for our purpose. More info.
5. Kernel#respond_to? # not important for our purpose. More info.
6. Monitor#mon_owned? # not important for our purpose. More info.
7. Array#sum # this is important because is the method we are calling from inside our code.
8. #toplevel # not important for our purpose.

How do you know which methods are and aren't related to your solution? Well is just a matter of experience. Searching and reading Ruby's documentation. And getting more familiar with the output you get while profiling your code. So long story short... Is easier to identify the more you profile.

B) Second. Now that we have filtered the information we can really look at what our method is doing inside.

From the step before we are left with:

• Object#sum_3
• Array#sum

This is saying that with only two steps we are solving the exercise. Isn't it great? also is saying in an implicit way that we are complying with some of the clean code qualities.

Simplicity and Readability.

Simplicity because you are assigning one responsibility to your method. In other words, your method is not trying to do a lot of things that could be apart.

We verify this because of the order that the steps are sort. First, comes the call to our method sum_3 and later the sum one. Also if we check the % time column (the first column). It makes sense to think that if my method sum_3 is wrapping the sum it should be where the most time is spent. Not the other way around.

• 0.34% of the time in sum_3 vs. 0.13% of the time in sum.

In case we didn't see this pattern. We'll have to reconsider, and split our method into smaller ones if necessary and possible.

Another thing to watch in the % time column is if our inside methods use more than 1% percent of the time. This indicates that we could improve that part.

In the example, this doesn't happen. But doesn't mean it can't improve. Is difficult to perceive improvement because our method is so simple. It only uses one method and is already in the most basic form. If we wanted to manipulate it we would have to mess with Ruby's classes... while possible it would generate a bigger mess.

Ok, let's think about it for a second. What is the "Array#sum" method doing? If we go to Ruby's documentation we will find this:

sum(init=0) → numbersum(init=0) {|e| expr } → number

Returns the sum of elements. For example, [e1, e2, e3].sum returns init + e1 + e2 + e3.

If a block is given, the block is applied to each element before addition.
If ary is empty, it returns init.

If we read between lines, what sum is doing is iterating through the elements in the array. This takes times as it does something like this pseudocode:

sum = 0

iterate through array do |number|
  sum += number

By now we have a lot of clues that can give us a better idea of how to improve our code.

This is the summary, at the moment:

1. It only does one thing and does it right. (simplicity)
2. Is understandable at first sight. (readable)
3. Is iterating through each element at a time.
4. The sum method can't be changed (Actually we can but we won't).
5. Is working as it returns the right answer.
6. And when you benchmark it, it was the most performant option.

In reality, our code is performing great! There is nothing much to do. The only thing that might be bothering you is the iteration.

Why? because Iterating through an array is time-consuming. So my next question to ask you is: What is better than iterating?

Well... no iterating at all. Wow, this sounds absurd! right?... But if you think about it, it doesn't.

So the next question to ask ourselves is, How to stop our sum method from iterating?

The answer is you don't.

At this point is where a programmer usually goes to Stack Overflow and start asking questions like:

• How to improve Ruby's Array#sum method?
• Best way to sum a collection of numbers in Ruby?
• Sum all elements in an array without iterating in Ruby?

You know this is true! and if you're not using it you should.

So you went to Stack Overflow and found that the best approach to sum all elements without iterating is the Mathematical way!. With this info, you made changes to your code and the result looks like this:

def sum_3(array)
  max_value = array.last # this because the array given is sorted. Also Array#max would be valid.
  (max_value**2 + max_value) / 2 # this is the mathematical way to sum all elements in a sorted collection that does not skip values.
end
  
  

So now you can sum sorted collections of numbers that start in 1 and end in

n

If you profile the new version you'll get this output:

 %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 30.52     0.00      0.00        1     0.65     0.65  Profiler__.start_profile
  1.27     0.00      0.00        1     0.03     0.04  Object#sum_3
  0.42     0.00      0.00        2     0.00     0.00  IO#set_encoding
  0.24     0.00      0.00        1     0.01     0.01  Module#method_added
  0.14     0.00      0.00        1     0.00     0.00  Kernel#respond_to?
  0.14     0.00      0.00        1     0.00     0.00  Integer#**
  0.09     0.00      0.00        1     0.00     0.00  Monitor#mon_owned?
  0.09     0.00      0.00        1     0.00     0.00  Array#last
  0.09     0.00      0.00        1     0.00     0.00  Integer#/
  0.09     0.00      0.00        1     0.00     0.00  Integer#+
  0.00     0.00      0.00        1     0.00     2.12  #toplevel

Let's analyze and get only the methods related to our new version sum_3:

1. 1.27 Object#sum_3
2. 0.14 Integer#**
3. 0.09 Array#last
4. 0.09 Integer#/
5. 0.09 Integer#+

It seems like we are doing more, but if we observe the % time column we can notice that the time the method spends solving the exercise is lower. Let's benchmark it to make sure is a better approach.

file_to_benchmark.rb

require 'benchmark/ips'

def array_sum(arr)
  arr.sum
end

def math_sum(arr)
  number = arr.last
  number**2 + number / 2
end

def benchmark(array)
  Benchmark.ips do |x|
    x.report('Array#sum') { array_sum(array) }
    x.report('mathematical sum') { math_sum(array) }
    x.compare!
  end
end

arr = [*(1..1000)]

benchmark(arr)

ruby file_to_benchmark.rb

Warming up --------------------------------------
           Array#sum    70.887k i/100ms
    mathematical sum   755.433k i/100ms
Calculating -------------------------------------
           Array#sum    697.066k (± 3.8%) i/s -      3.544M in   5.092828s
    mathematical sum      7.280M (± 4.9%) i/s -     37.016M in   5.097976s

Comparison:
    mathematical sum:  7279928.0 i/s
           Array#sum:   697065.7 i/s - 10.44x  (± 0.00) slower

Awesome!!!! With the changes made we managed to improve an already improved solution by making it 10.44 times faster than our initial approach!!!... To make you understand our initial approach was already fast enough!

Benchmarking and Profiling are worth doing!

Next time you work on an exercise try benchmarking and profiling your solutions. It will take time to analyze the results but it will be worth it!. You'll learn a lot and next time you won't have to do it as often because you will understand what you're doing.

Conclusion

Conclusion Ruby profiler is a tool, that is the next obvious step after benchmarking. It gives you clues and information that can really help you improve your code. Make it faster and less memory consuming.

It won't fix your code but will help your coding. Help your learning and give you a process that will maintain you curious about things.

You will be asking more questions. Wanting to know and understand what's happening under the hood. Why this and Why not that?

Understanding and applying this knowledge will give strength to your opinions. And your opinions will be solid as they will have facts that sustain them.