Ayende @ Rahien

My name is Oren Eini
Founder of Hibernating Rhinos LTD and RavenDB.
You can reach me by phone or email:


+972 52-548-6969

, @ Q c

Posts: 6,124 | Comments: 45,471

filter by tags archive

Bug hunting in a massively multi threaded environment

time to read 8 min | 1597 words

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"
    using(var session = store.OpenSession())
        session.Store(new ReadingList
            UserId = "test/1",
            Id = "lists/1",
            Books = new List<ReadingList.ReadBook>()
    Parallel.For(0, 100, i =>
        while (true)
                using (var session = store.OpenSession())
                    session.Advanced.UseOptimisticConcurrency = true;
                            .Books.Add(new ReadingList.ReadBook
                                ReadAt = DateTime.Now,
                                Title = "test " + i
            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));


And this one (where the exception is raised):

public override void WriteTo(JsonWriter writer, params JsonConverter[] converters)

    if (Items != null)
            foreach (var token in Items)
                token.WriteTo(writer, converters);
        catch (InvalidOperationException e)
            foreach (var stackTrace in addStackTraces)


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.



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

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


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.


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."


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.

Comment preview

Comments have been closed on this topic.


  1. RavenDB 3.5 whirl wind tour: You want all the data, you can’t handle all the data - about one day from now
  2. The design of RavenDB 4.0: Making Lucene reliable - 3 days from now
  3. RavenDB 3.5 whirl wind tour: I’ll find who is taking my I/O bandwidth and they SHALL pay - 4 days from now
  4. The design of RavenDB 4.0: Physically segregating collections - 5 days from now
  5. RavenDB 3.5 Whirlwind tour: I need to be free to explore my data - 6 days from now

And 14 more posts are pending...

There are posts all the way to May 30, 2016


  1. RavenDB 3.5 whirl wind tour (14):
    29 Apr 2016 - A large cluster goes into a bar and order N^2 drinks
  2. The design of RavenDB 4.0 (13):
    28 Apr 2016 - The implications of the blittable format
  3. Tasks for the new comer (2):
    15 Apr 2016 - Quartz.NET with RavenDB
  4. Code through the looking glass (5):
    18 Mar 2016 - And a linear search to rule them
  5. Find the bug (8):
    29 Feb 2016 - When you can't rely on your own identity
View all series



Main feed Feed Stats
Comments feed   Comments Feed Stats