Ruby Performance – Profile in optimizing Ruby performance – Part 4

In the previous sections, we have learned techniques for optimizing ruby ​​performance. But what if those techniques don’t work? The answer is a profile

The profile technique is the only way to answer the question cái gì làm cho code bị chậm? . In this article, we will explore the secrets in the profile that can easily find things that cause slow down in the program.

This article will have two main parts, that is, memory and CPU usage. Part 2 converts the previous result to show how the code is slow.

The tool used in the profile process is ruby-prof . It will measure the execution time of the program and will break down into the separate functions that the program uses.

After you make measurements from ruby-prof, you can visualize them with print tools built by ruby-prof or with KCachegrind.

Also, we need to specify the rule in the CPU profile. The first and only rule for a successful CPU profile process is to tắt garbage collector

Measured with Ruby-prof

ruby-prof is a Ruby gem including API and command-line tool. In Rails, we can test a request by adding ruby-prof in the middleware process.

1. ruby-prof API

For example:

We can use blocks for ruby-prof:

There are several types of reports for ruby-prof to print the results, above we use FlatPrinter , which will show the total execution time of each function. You will easily see which functions are time consuming for CPU.

When run, we will have a profile results as follows:

# ruby_prof_example_api1_profile.txt

Thread ID: 70237499659060

Fiber ID: 70237507374720

Total: 0.001111

Sort by: self_time

The above code spends more than 60% of the time searching for dates passed through a regular expression. Most of the remaining time is spent on Date#parse , which may be the initialization of the Date object.

Now, let’s learn how to use the command line.

2. The ruby-prof command line tool

We have the program:

We run the command ruby-prof to execute the above program profile:

-P option to specify output format for the profile. And -m to limit the display to all functions that take less than a specific time. In this case, there is no need to care which function runs less than 1%.

We have the result: Thread ID: 69883126035220

Fiber ID: 69883132260680

Total: 0.002094

Sort by: self_time

With the above profile, we can track which command takes the most time in the whole program. In this case, Kernel#gem_original_require , we can also see the time for the require 'date' command. In addition to instance initialization functions, classes also appear. Not surprisingly, with a simple program like this, the time for initialization is quite much compared to the necessary code.

Having a profile created with the ruby-prof tool will be helpful if you care about program optimization at startup and gem loading time. In other cases, it also adds a lot of data to the results, and you should use the ruby-prof API more.

3. Rails Middleware

The Ruby-prof API works best when you want to create a profile for a part of a Rails application, such as a controller action, or a time to render a template. But if you want to learn about middleware, routing or controller creation, you need to install ruby-prof like middleware.

To do this, add ruby-prof gem 'ruby-prof' to Gemfile: gem 'ruby-prof'

Add ruby-prof Rack Adapter to middleware, in config/application.rb

The use function will add the profiler below the middleware stack. So the profile will be added to the Rails initialization code, but bypassing the middleware. If you want to profile middleware, you need to add a profiler before Rack :: Runtime.

With Rack :: RubyProf middleware uploaded, you will get the results of the report saved in the path you installed above.

Don’t forget to disable GC before Rack :: RubyProf starts. The best way to do this is to write one or more middleware and prepend the profiler in the stack.

Visualize with Ruby-Prof Printer

Ruby-prof can generate many types of easy-to-understand reports. The three most common types are flat, call graph and call stack. Each type will have a different purpose. We will start with a more complex program that applies to each type of profiler:

The above program will generate a random CSV with a list of people and include birth dates, handle it and find the youngest from the list. We will print out 3 reports according to the 3 categories above. And the limit for printing functions takes more than 3% of the time.

Flat report: Find functions that run slowly

The flat profile displays the total time each function runs. For example, with the above program, we have:

Thread ID: 70137029546800

Fiber ID: 70137039955760

Total: 1.882948

Sort by: self_time

Inside:

%self : is the percentage of total time spent on this function.

total : is the total time lost for this function, including the function’s execution time when called.

self : is the time consumed by the function, excluding the execution time when it calls.

wait : is the waiting time for other threads. It will always be 0 with a single thread application.

child : is the time consumed in functions called from the current function

calls : is the total number of calls to that function

Flat reports are organized by time. So the functions at the top are the most time-consuming functions.

And the self time value in the report is the total running time of all calls to that function, regardless of any calls in the code. For example, the String#split function is called directly from parse_data and 50,000 times in the parse_row loop. In the report, we see that the String # split function is called all 50,001 times.

Please note that self time does not include the time for nested function calls. For example, Object # parse_col’s self time does not include regular expresson runtime or date compilation. Although with a simple function with only an if-else expression, Object # parse_col still takes a considerable amount of time.

We all know, the top function is the slowest run. So it needs to be optimized first. But the optimization process is not easy. It cannot optimize the slowest function by self time, for 2 reasons:

• Profiler only reports a large amount of self time for a function even when you speed it up. For example, Object # parse_col does nothing in this. This is all due to the implementation of the if-else expression ..
• The slowest function can be a good library function or is simple enough that you can’t optimize. For example, Array # map is the 3rd slowest function. But it’s a library and we can’t directly fix it.

Both of these cases are actually due to the number of function calls rather than the code within the function. Therefore, the most effective way to optimize is to reduce the number of function calls. And you need to know where and how often the function is called. But in the flat report does not show that. So, you need another profile, that is the graph report.

Graph report: Understand which parts of the code are slow

Graph reports are organized by the total number of times the function was run, including the time since the function called.

Thread ID: 70137029546800

Fiber ID: 70137039955760

Total Time: 1.8829480049999994

Sort by: total_time

The meaning of the columns is similar to the flat report. But the function calls will be immediately placed above and the called calls will be placed below.

The second line is Array # map! require more effort. The function runs in the middle, because it includes both the 3 calls above and the 2 calls below.

Calls column shows Array # map! 50,002 times: 50,000 times from Object # parse_now, one is from Object # find_youngest, and one is from Object # parse_data.

The timing column gives a different meaning to the call. Each call will display total, self and child that Array # map! needed when the call is executed.

The useful information from that report is first, we can get a good overview of where the program runs. For example, the program runs almost 90% of the time data processing the CSV stream. Secondly, we can track the profile from top to bottom to indicate the idea of ​​what code we should optimize. For example, we can see the slowest function through the total time Array # map! call Object # parse_row. That is called String # split, there is quite a lot of self time. So one way to optimize is to reduce the number of String # split calls or replace them with other functions.