Chapter
2
Fix Common Performance Problems
There is nothing new under the sun.
The reasons code is slow invariably come down to familiar issues. This is especially true for us Ruby developers. We are far removed from writing bare-metal code. We heavily use language features, standard libraries, gems, and frameworks. And each of these brings along its performance issues. Some of these are actually memory inefficient by design! We should be extremely careful about how we write our code and what features or libraries we use.
We have talked about two of the common reasons for poor performance in the previous chapter: extra memory allocation and data structure copying. What are the others?
Execution context copying, memory-heavy iterators, slow type conversions, and iterator-unsafe functions are a few of the culprits. In the next pages I’ll walk you through the steps to avoid these. But before we start, let’s briefly talk about a subject we’ve avoided so far: measurements.
We need some way to know that the changes we make really improve performance. In the previous chapter we used Benchmark.realtime to measure execution time and ‘ps -o rss= -p #{Process.pid}‘.to_i to measure current memory usage. To understand how reduced memory usage translates into the improved performance, we’ll also measure the number of GC calls and the time required for GC. The former is easy to measure. Ruby provides the GC#stat function that returns the number of GC runs (and more stats that we’ll ignore for now). The latter is harder, and requires running the same program twice, once with GC disabled, and getting a difference you can attribute to GC.
Let’s build a tool. We’ll create a wrapper function that will measure execution time, the number of GC runs, and total allocated memory. In addition to that, let’s make the function read the --no-gc command-line option and turn off GC if requested.
| chp2/wrapper.rb | |
| | require "json" |
| | require "benchmark" |
| | |
| | def measure(&block) |
| | no_gc = (ARGV[0] == "--no-gc") |
| | |
| | if no_gc |
| | GC.disable |
| | else |
| | # collect memory allocated during library loading |
| | # and our own code before the measurement |
| | GC.start |
| | end |
| | |
| | memory_before = `ps -o rss= -p #{Process.pid}`.to_i/1024 |
| | gc_stat_before = GC.stat |
| | time = Benchmark.realtime do |
| | yield |
| | end |
| | puts ObjectSpace.count_objects |
| | unless no_gc |
| | GC.start(full_mark: true, immediate_sweep: true, immediate_mark: false) |
| | end |
| | puts ObjectSpace.count_objects |
| | gc_stat_after = GC.stat |
| | memory_after = `ps -o rss= -p #{Process.pid}`.to_i/1024 |
| | |
| | puts({ |
| | RUBY_VERSION => { |
| | gc: no_gc ? 'disabled' : 'enabled', |
| | time: time.round(2), |
| | gc_count: gc_stat_after[:count] - gc_stat_before[:count], |
| | memory: "%d MB" % (memory_after - memory_before) |
| | } |
| | }.to_json) |
| | end |
OK, there’s another way to measure GC time: the GC::Profiler that Ruby 1.9.2 introduced. The problem is that it adds significant overhead to both memory and CPU. This is good for profiling where absolute numbers are not important and you’re interested only in relative values. It’s less useful for measurements that we want to do in this chapter.
Memory measurements with and without GC will of course differ. In the former case, we will get the amount of memory allocated by the block that stays allocated after we’re done. We’ll use this number to find memory leaks. In the latter case, we’ll get total memory consumption: the amount of memory allocated during the execution of the block. That’s the metric we’ll use most often in this chapter, as it directly shows how much work your program makes for the GC.
So let’s do some measuring. Let’s use the wrapper to run our unoptimized code example from the previous chapter. Here and later in this chapter I will use Ruby 2.2 to run my examples unless otherwise noted.
| chp2/wrapper_example.rb | |
| | require 'wrapper' |
| | require 'csv' |
| | |
| | measure do |
| | data = CSV.open("data.csv") |
| | output = data.readlines.map do |line| |
| | line.map { |col| col.downcase.gsub(/('?[a-z])/) { $1.capitalize } } |
| | end |
| | File.open("output.csv", "w+") { |f| f.write output.join("
") } |
| | end |
| | $ cd code/chp2 |
| | $ ruby -I . wrapper_example.rb |
| | {"2.2.0":{"gc":"enabled","time":14.96,"gc_count":27,"memory":"479 MB"}} |
| | $ ruby -I . wrapper_example.rb --no-gc |
| | {"2.2.0":{"gc":"disabled","time":10.17,"gc_count":0,"memory":"1555 MB"}} |
The results are exactly what we saw before. But in addition, we see that GC kicked off 27 times during execution. As usual with these measurements, you will have to run the wrapper several times to obtain (more or less) accurate measurement. But there’s no need yet to aim for statistical significance. We’ll handle that problem later.
So let’s take this wrapper as a basic measurement tool and see what is slow in Ruby and how to fix it.