Hunting down obscure GC bugs
It has been approximately a year since my copy-on-write work on the Ruby garbage collector was released in a form that’s suitable for production environments, namely in the form of Ruby Enterprise Edition. In the past half year its usage has grown dramatically, being adopted by, among others, New York Times, Shopify and 37signals.
However, there are a few reports of REE freezing after a while, and it seems to occur randomly. A few people have posted backtraces of the affected Ruby processes, and the backtrace always shows the function finalize_list. Sometimes the backtrace shows that the topmost function in the call stack is st_delete, and sometimes it does not.
Is there anything more frustrating to a programmer who wants to help, than not being able to reproduce the problem? I could not reproduce it at all, not on my development machine and not on any of our servers. The problem seems to be rare because otherwise a lot more people should have reported this. There’s only one way to combat this problem: the hard way, by performing a thorough code inspection. This is not an easy task because the garbage collector source file, gc.c, consists of 2945 lines. There are about 10 lines of non-API comments, of which 7 are written by myself. There are many idoms in the Ruby code base that are hard to read.
Let’s start at st_delete, located at st.c. st.c is an implementation of a hash table, used all over the place in the Ruby codebase, for example for storing instance variables in a class. The st_delete function is for – can you guess it – deleting an entry from a hash table. Can this function loop infinitely?
-
int
-
st_delete(table, key, value)
-
register st_table *table;
-
register st_data_t *key;
-
st_data_t *value;
-
{
-
unsigned int hash_val;
-
st_table_entry *tmp;
-
register st_table_entry *ptr;
-
-
hash_val = do_hash_bin(*key, table);
-
ptr = table->bins[hash_val];
-
-
if (ptr == 0) {
-
if (value != 0) *value = 0;
-
return 0;
-
}
-
-
if (EQUAL(table, *key, ptr->key)) {
-
table->bins[hash_val] = ptr->next;
-
table->num_entries–;
-
if (value != 0) *value = ptr->record;
-
*key = ptr->key;
-
free(ptr);
-
return 1;
-
}
-
-
for(; ptr->next != 0; ptr = ptr->next) {
-
if (EQUAL(table, ptr->next->key, *key)) {
-
tmp = ptr->next;
-
ptr->next = ptr->next->next;
-
table->num_entries–;
-
if (value != 0) *value = tmp->record;
-
*key = tmp->key;
-
free(tmp);
-
return 1;
-
}
-
}
-
-
return 0;
-
}
There is at least one infinite looping candidate in this function: the for loop in the bottom part of the function. The only way in which the ‘for’ loop can be infinite is if the linked list that the hash bucket refers to has a circular reference.
st_delete is called by run_final in gc.c. run_final runs all finalizers on a given object. Finalizers are pieces of codes that can be attached to an object. They are run some time after the garbage collector has freed an object. For example, socket objects have finalizers that close the underlying socket connection.
The run_final function looks like this:
-
static void
-
run_final(obj)
-
VALUE obj;
-
{
-
long i;
-
int status, critical_save = rb_thread_critical;
-
VALUE args[3], table, objid;
-
-
objid = rb_obj_id(obj); /* make obj into id */
-
rb_thread_critical = Qtrue;
-
args[1] = 0;
-
args[2] = (VALUE)ruby_safe_level;
-
for (i=0; i<RARRAY(finalizers)->len; i++) {
-
args[0] = RARRAY(finalizers)->ptr[i];
-
if (!args[1]) args[1] = rb_ary_new3(1, objid);
-
rb_protect((VALUE(*)_((VALUE)))run_single_final, (VALUE)args, &status);
-
}
-
if (finalizer_table && st_delete(finalizer_table, (st_data_t*)&obj, &table)) {
-
for (i=0; i<RARRAY(table)->len; i++) {
-
VALUE final = RARRAY(table)->ptr[i];
-
args[0] = RARRAY(final)->ptr[1];
-
if (!args[1]) args[1] = rb_ary_new3(1, objid);
-
args[2] = FIX2INT(RARRAY(final)->ptr[0]);
-
rb_protect((VALUE(*)_((VALUE)))run_single_final, (VALUE)args, &status);
-
}
-
}
-
rb_thread_critical = critical_save;
-
}
There are two loops in this function, and both will always terminate because RARRAY(...)->len is bounded.
run_final is called by finalize_list. This function loops through a list of objects and calls run_final on each object:
-
static void
-
finalize_list(p)
-
RVALUE *p;
-
{
-
while (p) {
-
RVALUE *tmp = p->as.free.next;
-
run_final((VALUE)p);
-
/* Don’t free objects that are singletons, or objects that are already freed.
-
* The latter is to prevent the unnecessary marking of memory pages as dirty,
-
* which can destroy copy-on-write semantics.
-
*/
-
if (!FL_TEST(p, FL_SINGLETON) && p->as.free.flags != 0) {
-
p->as.free.flags = 0;
-
p->as.free.next = freelist;
-
rb_mark_table_remove(p);
-
freelist = p;
-
}
-
p = tmp;
-
}
-
}
This function can loop infinitely if the linked list (p) has a circular reference.
The list of possible culprits that I’ve compiled so far is not exhaustive. Although unlikely, *any* function called by one of these functions could contain an infinite loop. It’s almost impossible to review all possible code paths. Indeed, I’ve struggled with this problem for months, unable to find out the cause, or even verify that it’s indeed REE’s fault and not the fault of some native extension.
Until last week, that is. I’ve been working with Joshua Sierles, system administrator at 37signals, to solve this problem. Once in a while one of their REE processes would freeze in an infinite loop, called from finalize_list. One of the many things that we had tried is to inspect such stuck processes with gdb, but their REE binaries didn’t have debugging symbols. So after reinstalling REE with debugging symbols and after some debugging sessions, we were able to infer that the infinite loop occurs in finalize_list: the linked list contains a circular reference!
But how can such a circular reference occur? This infinite looping bug doesn’t occur in normal Ruby, so it’s probably an REE-specific bug. The fact that the infinite loop occurs in finalize_list probably means that I have a bug somewhere in the finalizers handling code, so I decided to inspect all finalizers-related code that I’ve modified. After spending a lot of time digging through the source code, I could not find any obvious places that could create circular references in the finalizers list, but I did remember an interesting change that I made in the past. Consider the following code in gc_mark_all() in the original Ruby source code:
-
while (p < pend) {
-
if ((p->as.basic.flags & FL_MARK) &&
-
(p->as.basic.flags != FL_MARK)) {
-
gc_mark_children((VALUE)p, 0);
-
}
-
p++;
-
}
Standard Ruby uses the FL_MARK flag in the ‘flags’ member to indicate that an object is marked by the garbage collector. This makes the above ‘if’ statement especially interesting: it checks whether FL_MARK is set, but it also checks whether FL_MARK isn’t the only flag in the ‘flags’ field. I didn’t fully understand what this means, but I did understand that because of this I can’t just get rid of the FL_MARK flag, and replace FL_MARK bitmask operations with calls to the mark table. This code here tells me that the codebase assumes that if an object is marked, then its flags is not 0 (a flag of 0 means that the object is a free slot). If I naively replace FL_MARK operations with mark table calls then this assumption will be violated. So I introduced the FL_ALLOCATED flag. Every object that is not free will have this flag set. Then I changed the ‘if’ statement to:
-
if (rb_mark_table_heap_contains(heap, p) &&
-
(p->as.basic.flags != FL_ALLOCATED)) {
-
gc_mark_children((VALUE)p, 0);
-
}
This should have the same semantics as the original, or so I thought. After all it checks whether the object is marked, but whether it’s not the case that there are no other flags set.
Consider also this code in gc_sweep(), the function that frees all non-marked objects:
-
while (p < pend) {
-
if (!(p->as.basic.flags & FL_MARK)) {
-
if (p->as.basic.flags) {
-
obj_free((VALUE)p);
-
}
-
if (need_call_final && FL_TEST(p, FL_FINALIZE)) {
-
p->as.free.flags = FL_MARK; /* remain marked */
-
p->as.free.next = final_list;
-
final_list = p;
-
}
-
else {
-
p->as.free.flags = 0;
-
p->as.free.next = freelist;
-
freelist = p;
-
}
-
n++;
-
}
-
else if (RBASIC(p)->flags == FL_MARK) {
-
/* objects to be finalized */
-
/* do nothing remain marked */
-
}
-
else {
-
RBASIC(p)->flags &= ~FL_MARK;
-
live++;
-
}
-
p++;
-
}
This piece of code iterates through a Ruby heap, and frees the objects that are not marked.
if (need_call_final && FL_TEST(p, FL_FINALIZE)) { checks whether the current object has any finalizers.
The line else if (RBASIC(p)->flags == FL_MARK) { is similar to the check in gc_mark_all(). I replaced this line with else if (RBASIC(p)->flags == FL_ALLOCATED) {
I also changed the line p->as.free.flags = FL_MARK; /* remain marked */ to rb_mark_table_heap_add(heap, p); /* remain marked */
Because of the recent code inspection, I discovered that the latter change is not correct. The original code not only keeps the object marked, but it also removes all other flags. I wondered whether this may have anything to do with the infinite loop bug. So I inserted the following code before the rb_mark_table_heap_add call:
-
p->as.free.flags = FL_ALLOCATED;
The semantics should now be equal to the original’s… right?
It is clear that if I do not insert this call, then the object’s existing flags will be preserved. p->as.basic.flags != FL_MARK in gc_mark_all() will then always be true and RBASIC(p)->flags == FL_MARK will always be false. This is clearly undesirable.
After some testing, it would seem that the change doesn’t break anything. The resulting Ruby interpreter was able to install the Rails gem and generate the rdoc for it, a fairly memory-intensive operation. However, I wasn’t sure whether this also tests the finalizers handling code. Then the thought that finalizers could be plain Ruby code and thus could trigger a garbage collection occurred to me. If I trigger a garbage collection inside a finalizer, will things break?
-
def foo
-
x = "hello world"
-
ObjectSpace.define_finalizer(x, lambda { |x| GC.start })
-
x = nil
-
end
-
-
def bar
-
x = 1 + 1
-
y = x * 2
-
["", "", ""]
-
return y * 3
-
end
-
-
5000.times do |i|
-
foo
-
end
-
puts "done"
Yes. Yes it will, as was clear after executing the above test script that I wrote. It would cause Ruby to abort with a message along the lines of “rb_gc_mark(): unknown data type 0×0(0xYYYY) corrupted object”. This is certainly very suspicious. Does this mean that my change w.r.t. FL_ALLOCATED is incorrect, and could be the cause of the infinite loop bug?
I spent several hours debugging this with gdb, but at the end of the day I was still as clueless as several hours ago. I knew that something went wrong, but I didn’t know why. But that was probably because I was tired. The next morning I found the solution. I spent an hour thinking about what the original code is actually trying to do, something which I didn’t fully understand before.
- I figured that the == FL_MARK, != FL_MARK and = FL_MARK code must have something to do with finalizers.
- The code around = FL_MARK is trying to keep the object alive so that it could be finalized later. This makes sense. In addition, it is apparently also a guard that prevents any garbage collection runs invoked by any of the finalizers from freeing this object. It does so by making sure that RBASIC(p)->flag == FL_MARK returns true. This prevents gc_sweep from removing the object’s marking in the ‘else’ block.
- In a standard mark-and-sweep implementation, all objects will be unmarked after a garbage collection run. The previous findings imply that this is not the case in Ruby’s implementation! My copy-on-write friendly mark table clears all markings after a garbage collection run, which is apparently not correct.
So setting an object’s flag to FL_MARK actually means that the object is to be finalized later, and should not be freed until its finalizer has run. == FL_MARK actually checks whether an object is marked to be finalized later, and != FL_MARK checks the negation.
With this in mind, I made the following changes: http://github.com/FooBarWidget/rubyenterpriseedition/commit/63247bf87b11c9acc2dfd1ed5f98b1ed8dd4c780
I removed the FL_ALLOCATED flag and introduced an FL_DEFER_FINALIZE flag. I replaced the FL_MARK bitmask checks with FL_DEFER_FINALIZE checks. This change has been tested in production for a while now by 37signals. Everything’s been running smoothly ever since.
I’d really like to thank Joshua for his patience. Thanks to the debugging sessions that he made possible, I was able to finally track down the cause of the infinite loop bug.
We’re going to release a new version of Ruby Enterprise Edition soon, which includes this bug fix.
It’s amazing sometimes how so much thinking work only results in 10 lines of code. If you like my work, please consider sending a donation and/or to recommend me on Working With Rails. Thank you. 
