Measuring Ruby Garbage Collector

I wanted to measure the GC after reading articles from the Shopify team. Some of their slowest requests are because of garbage collection. I was curious to know if that was the case for RoRvsWild too.

One practical way to observe how garbage collection affects response time is to add GC.start to a controller. Running the GC pauses the request until it has finished. I encourage you to try it in your current localhost application.

Fortunately, there is no garbage collection for each request. However, the garbage collector may have to clean objects from previous requests, and the current request can be slow because of previous allocations. Thus, GC timing on a specific request is not always relevant. It is essential to measure global garbage collection among all requests.

Generational garbage collector

To improve speed, the GC splits objects into two categories: new and old. New objects are more likely to be unreferenced, and old objects are more likely to be referenced until the end of the program.

A minor garbage collection walks through new objects only. A major garbage collection walks through both new and old objects. That explains why minor garbage collection is faster and why you want to avoid major garbage collection.

Nonetheless, by default, GC.start runs a major garbage collection. You can run a minor with GC.start(full_mark: false), which is much faster for a Ruby on Rails application.

Measuring garbage collection

To measure, I only need to know how many times it ran and for how long.

The GC.count method returns the number of garbage collections. It includes both minor and major. GC.stat[:minor_gc_count] and GC.stat[:major_gc_count] allow for specific counts. But in my case, the global GC.count is enough because I am interested in the total GC time.

Since Ruby 3.1, GC.total_time has been added, which returns the GC timing in nanoseconds as integer. It is enabled by default and can be changed with GC.measure_total_time=.

Before 3.1, the only way was to call GC::Profiler.total_time which returns the GC timing in seconds as a float. It is disabled by default and has to be enabled with GC::Profiler.enable.

So, there are 2 methods with the same name, but they return different units and types, and one might be disabled when the other is enabled by default. It’s inconsistent and problematic when measuring GC timing for different Ruby versions. The solution is to wrap everything into a method with some duck typing:

class RorVsWild
  if GC.respond_to?(:total_time) # Ruby >= 3.1
    def self.gc_total_ms
      GC.total_time / 1_000_000.0 # nanosecond -> millisecond
    end
  else # Ruby < 3.1
    def self.gc_total_ms
      GC::Profiler.total_time * 1_000 # second -> millisecond
    end
  end
end

RorVsWild.gc_total_ms # Returns always milliseconds for all Ruby versions

The condition with respond_to is outside the method definition for performance reasons. Therefore, it is called only once.

By suffixing the name with the unit, it’s obvious and less error-prone. It does not tell if it’s an integer or a float, but I think it’s more important to know the unit than the type.

All that remains is to call GC.count and gc_total_ms at the beginning and end of each request. Then, the differences have to be stored somewhere.

From the just released version 1.8.0, RorVsWild’s agent automatically measures garbage collections. If your Ruby version is before 3.1, do not forget to call GC::Profiler.enable. You will know easily how much time is spent by the GC.

Conclusion

Thanks to the Ruby Core library, measuring garbage collection isn’t difficult, even if there are differences between versions.

For RoRvsWild, the GC consumes 1% of request time and 3% for jobs. If the GC consumes too much time, it’s probably because major collections are too frequent and there are too many old objects.

Finally, I would encourage you to read Adventures in Garbage Collection: Improving GC Performance in our Massive Monolith and discover how Jean Boussier from Shopify succeeded in limiting major garbage collections.