Measure Memory Yourself with GC#stat and GC::Profiler
You need to make manual measurements to profile memory without RailsExpress patches. We want to measure memory usage and GC statistics, print and collect them, then analyze them. That’s a lot of work, but sometimes it’s our only option. For example, a memory leak might happen in production only. We certainly don’t want to run production inside the profiler—that would slow it down. But we can insert the measurement code instead.
The first thing we want to measure is the current memory usage. As we discussed earlier, it’s less relevant than the memory usage deltas that we saw in ruby-prof, but in production, it’s the only number we can get.
The best way to measure memory is to ask the operating system, as we did earlier in the book.
| | memory_before = `ps -o rss= -p #{Process.pid}`.to_i/1024 |
| | do_something |
| | memory_after = `ps -o rss= -p #{Process.pid}`.to_i/1024 |
This of course works only on Unix operating systems.
A multiplatform approach is to ask Ruby for the GC statistics, but as we already discussed that’s even less useful than measuring current memory usage. But if we have reproducible high memory usage or a leak in production, we can definitely collect GC statistics to get an idea of what happens there.
You can get GC statistics in one of two ways. You can manually collect data by calling GC#stat in several places in your code. Or you can use GC::Profiler, available in Ruby 1.9.3 and later. Let me show you both in an irb session.
| | 2.1.4 :001 > GC.stat |
| | => {:count=>7, :heap_used=>81, :heap_length=>81, :heap_increment=>0, |
| | :heap_live_slot=>32578, :heap_free_slot=>438, |
| | :heap_final_slot=>0, :heap_swept_slot=>19535, |
| | :heap_eden_page_length=>81, :heap_tomb_page_length=>0, |
| | «…» |
| | :oldmalloc_increase=>2162848, :oldmalloc_limit=>16777216} |
| | 2.1.4 :002 > x = "x"*1024*1024*100; nil # allocate 100 MB of memory |
| | => nil |
| | 2.1.4 :003 > GC.stat |
| | => {:count=>9, :heap_used=>81, :heap_length=>81, :heap_increment=>0, |
| | :heap_live_slot=>12785, :heap_free_slot=>20231, |
| | :heap_final_slot=>0, :heap_swept_slot=>20479, |
| | :heap_eden_page_length=>81, :heap_tomb_page_length=>0, |
| | «…» |
| | :oldmalloc_increase=>4776, :oldmalloc_limit=16777216 } |
| | 2.1.4 :004 > GC::Profiler.enable |
| | 2.1.4 :005 > y = "y"*1024*1024*100; nil # allocate another 100 MB of memory |
| | => nil |
| | 2.1.4 :006 > GC::Profiler.report |
| | GC 10 invokes. |
| | Index Invoke Time(sec) Use Size(b) Total Size(b) Total Object GC Time(ms) |
| | 1 0.171 505320 1321920 33048 0.755 |
| | => nil |
| | 2.1.4 :007 > GC::Profiler.disable |
| | => nil |
Here we’ve allocated a 100 MB string twice and measured GC statistics first with GC#stat, then with GC::Profiler.
To fully understand all the numbers reported by GC#stat you need to know the Ruby GC architecture. We’ll look at that later in Chapter 10, Tune Up the Garbage Collector. But even without knowing the internals, you can see that the GC count increased from 7 to 9, meaning that Ruby called the garbage collector twice during the string allocation. We also allocated more objects on the Ruby heap, but not enough to increase it. The heap still has 81 slots, with more than half of them free. The 100 MB of memory we allocated went to the operating system heap and wasn’t reported here.
GC::Profiler gives us the same information but in a human-readable form. Instead of heap slots numbers we see bytes. We also get GC time. In our case GC was invoked ten times. Nine of them happened before GC::Profiler, and one during profiling. Our example doesn’t create a lot of new Ruby objects, so heap usage and total size don’t interest us. GC time does. As you see, the single collection pass took almost 800 ms. That’s huge, and it’s definitely something we’d want to optimize if it were production code.