Ayende @ Rahien

It's a girl

Bug hunting in a massively multi threaded environment

We got a really nasty bug report from a user. Sometimes, out of the blue, RavenDB would throw an error:

System.InvalidOperationException: Collection was modified; enumeration operation may not execute.
at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
at Raven.Json.Linq.RavenJArray.WriteTo(JsonWriter writer, JsonConverter[] converters) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJArray.cs:line 174
at Raven.Json.Linq.RavenJObject.WriteTo(JsonWriter writer, JsonConverter[] converters) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJObject.cs:line 275 at Raven.Json.Linq.RavenJObject.WriteTo(JsonWriter writer, JsonConverter[] converters) in c:\Builds\RavenDB-Stable\Raven.Abstractions\Json\Linq\RavenJObject.cs:line 275

Unfortunately, this error only happened once in a while, usually when the system was under load. But they weren’t able to provide a repro for that.

Luckily, they were able to tell us that they suspected that this is related to the replication support. I quickly setup a database with replication and wrote the following code to try to reproduce this:

using(var store = new DocumentStore
{
    Url = "http://localhost:8080",
    DefaultDatabase = "hello"
}.Initialize())
{
    using(var session = store.OpenSession())
    {
        session.Store(new ReadingList
        {
            UserId = "test/1",
            Id = "lists/1",
            Books = new List<ReadingList.ReadBook>()
        });
        session.SaveChanges();
    }
    Parallel.For(0, 100, i =>
    {
        while (true)
        {
            try
            {
                using (var session = store.OpenSession())
                {
                    session.Advanced.UseOptimisticConcurrency = true;
                    session.Load<ReadingList>("lists/1")
                            .Books.Add(new ReadingList.ReadBook
                            {
                                ReadAt = DateTime.Now,
                                Title = "test " + i
                            });
                    session.SaveChanges();
                }
                break;
            }
            catch (ConcurrencyException)
            {
                
            }
        }
    });
}

And that reproduced the bug! Hurrah! Done deal, we can move on, right?

Except that the bug was only there when we have massive amount of threads hitting the db at once, and trying to figure out what is actually going on there was next to impossible using standard debugging tools. Instead, I reached down to my tracing toolbelt and starting pulling stuff out. First, we identified that the problem occurred when iterating over RavenJArray, which is our own object, so we added the following:

        ConcurrentQueue<StackTrace>  addStackTraces = new ConcurrentQueue<StackTrace>();

        public void Add(RavenJToken token)
        {
            if (isSnapshot)
                throw new InvalidOperationException("Cannot modify a snapshot, this is probably a bug");

            addStackTraces.Enqueue(new StackTrace(true));

            Items.Add(token);
        }

And this one (where the exception is raised):

public override void WriteTo(JsonWriter writer, params JsonConverter[] converters)
{
    writer.WriteStartArray();

    if (Items != null)
    {
        try
        {
            foreach (var token in Items)
            {
                token.WriteTo(writer, converters);
            }
        }
        catch (InvalidOperationException e)
        {
            foreach (var stackTrace in addStackTraces)
            {
                Console.WriteLine(stackTrace);
            }
            throw;
        }
    }

    writer.WriteEndArray();
}

With the idea that we would actually be able to get what is going on there. By tracking down who added items to this particular instance, I hoped that I would be able to figure out why we have an instance that is shared among multiple threads.

When I had that, it was pretty easy to see that it was indeed the replication bundle that was causing the issue. The problem was that the replication bundle was modifying an inner array inside the document metadata. We protected the root properties of the metadata from concurrent modifications, and most of the time, it works just fine. But the problem was that now we had a bundle that was modifying a nested array, which wasn’t protected.

This is one of those bugs that are really hard to catch:

  • My understanding of the code said that this is not possible, since I believed that we protected the nested properties as well*.
  • This bug will only surface if and only if:
    • You have the replication bundle enabled.
    • You have a great deal of concurrent modifications (with optimistic concurrency enabled) to the same document.
    • You are unlucky.

I was grateful that the user figured out the replication connection, because I already sat on that bug previously, and there was no way I could figure out what is going on unless I had the trace to point me to where the actual problem was.

Comments

configurator
02/18/2013 02:15 PM by
configurator

Try using IntelliTrace (part of Visual Studio 2012 Ultimate) next time. It can record events (you can tell it which events to record), or even every single function call (which is useful for tests, but horribly slow for any interactive software), and then you can debug multi-threaded code much more easily.

Ayende Rahien
02/18/2013 03:09 PM by
Ayende Rahien

Dor, I never really got IntelliTrace, and anything that has significant perf cost is going to be problematic for multi threaded issues.

configurator
02/18/2013 03:47 PM by
configurator

Basically, you enable it and run the test. You put a breakpoint on the point where the test failed, then (assuming it still fails), you can go backwards in time. You basically get the same debug environment as usual (with step over, step into, watch, etc.), but you can also step back in execution and redo the test. And it does the exact same thing, i.e. timing issues still happen because you're just moving the time line back and forward without actually executing anything.

It's got a bit of a learning curve, but it's extremely useful, especially in these sort of circumstances. I suggest when using it to always have the Parallel Stacks window open on a second monitor at all times; it makes things somewhat easier to follow.

Mario
02/18/2013 03:54 PM by
Mario

Ayende say's

"We protected the root properties of the metadata from concurrent modifications, and most of the time, it works just fine. But the problem was that now we had a bundle that was modifying a nested array, which wasn’t protected."

...wow

Vlad Kosarev
02/19/2013 10:42 PM by
Vlad Kosarev

Thanks for fixing this one Oren. Sometimes it's really hard to give you a reproduction demo without giving you the whole product. With sufficiently complex systems we don't know which part of complexity breaks raven. We just know that the issue is in Raven. Trust me when it's not that we don't try. I think first time we hit this we spent a week trying to replicate the issue in a demo app and we couldn't. That's how we figured it could've been replication (we usually don't run it locally).

It does help to build local raven and debug that to see where you can trigger an issue but sometimes that's just not possible.

There are still interesting threading issues that we see (we have some queries that if we run 24 threads or less with them, raven is cool, if we run 25 threads and up first Transaction breaks). These aren't as important right now but there will be more threading holes and hopefully it will be easy to reproduce in a test.

Comments have been closed on this topic.