Here is another video about RavenDB, this time it is me and Seth Juarez discussing RavenDB on DevExpress TV.

As an aside, it is also me using Seth for user study of the API

I just got the following bug report, I’ll just let you read it, and I have additional commentary below:

The great fun with getting a pull request with a failing test is that the whole process of working with this is pretty seamless.

For the one above, GitHub told me that I need to run the following command:

git pull https://github.com/benjamingram/ravendb.git DynamicFieldsBug

I did, and got the failing test, from there it was just a matter of fixing the actual bug, which was rather simple, and nothing that even smelled like ceremony.

This is what I got when I was trying to figure out an OutOfMemoryException in RavenDB

Originally posted at 1/18/2011

We got some reports that there was an O(N) issue with loading large number of documents from Raven.

I wrote the following test code:

var db = new DocumentDatabase(new RavenConfiguration
{
    DataDirectory = "Data"
});
Console.WriteLine("Ready");
Console.ReadLine();
while (true)
{
    var sp = Stopwatch.StartNew();

    db.Query("Raven/DocumentsByEntityName", new IndexQuery
    {
        Query = "Tag:Item",
        PageSize = 1024
    });

    Console.WriteLine(sp.ElapsedMilliseconds);
}

With 1,024 documents in the database, I could clearly see that most requests took in the order of 300 ms. Not content with that speed, I decided to dig deeper, and pulled out my trusty profiler (dotTrace, and no, I am not getting paid for this) and got this:

As should be clear, it seems like de-serializing the data from byte[] to a JObject instance is taking a lot of time (relatively speaking).

To be more precise, it takes 0.4 ms, to do two deserialization operations (for the following document):

{
    "cartId": 666,
    "otherStuff": "moohahaha",
    "itemList": [{
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    },
    {
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    },
    {
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    },
    {
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    },
    {
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    },
    {
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    },
    {
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    },
    {
        "productId": 42,
        "name": "brimstone",
        "price": 6.66,
        "quantity": 2000
    }]
}

I found it quite surprising, to tell you the truth. I wrote the following test case to prove this:

static void Main()
{
    
    var st =
        "IQAAAAJSYXZlbi1FbnRpdHktTmFtZQAFAAAASXRlbQAAvgIAABJjYXJ0SWQAmgIAAAAAAAACb3RoZXJTdHVm"+
        "ZgAKAAAAbW9vaGFoYWhhAARpdGVtTGlzdACFAgAAAzAATQAAABJwcm9kdWN0SWQAKgAAAAAAAAACbmFtZQAKA"+
        "AAAYnJpbXN0b25lAAFwcmljZQCkcD0K16MaQBJxdWFudGl0eQDQBwAAAAAAAAADMQBNAAAAEnByb2R1Y3RJZAA"+
        "qAAAAAAAAAAJuYW1lAAoAAABicmltc3RvbmUAAXByaWNlAKRwPQrXoxpAEnF1YW50aXR5ANAHAAAAAAAAAAMy"+
        "AE0AAAAScHJvZHVjdElkACoAAAAAAAAAAm5hbWUACgAAAGJyaW1zdG9uZQABcHJpY2UApHA9CtejGkAScXVhbn"+
        "RpdHkA0AcAAAAAAAAAAzMATQAAABJwcm9kdWN0SWQAKgAAAAAAAAACbmFtZQAKAAAAYnJpbXN0b25lAAFwcmljZ"+
        "QCkcD0K16MaQBJxdWFudGl0eQDQBwAAAAAAAAADNABNAAAAEnByb2R1Y3RJZAAqAAAAAAAAAAJuYW1lAAoAAABi"+
        "cmltc3RvbmUAAXByaWNlAKRwPQrXoxpAEnF1YW50aXR5ANAHAAAAAAAAAAM1AE0AAAAScHJvZHVjdElkACoAAAAAA"+
        "AAAAm5hbWUACgAAAGJyaW1zdG9uZQABcHJpY2UApHA9CtejGkAScXVhbnRpdHkA0AcAAAAAAAAAAzYATQAAABJwcm9"+
        "kdWN0SWQAKgAAAAAAAAACbmFtZQAKAAAAYnJpbXN0b25lAAFwcmljZQCkcD0K16MaQBJxdWFudGl0eQDQBwAAAAAAAA"+
        "ADNwBNAAAAEnByb2R1Y3RJZAAqAAAAAAAAAAJuYW1lAAoAAABicmltc3RvbmUAAXByaWNlAKRwPQrXoxpAEnF1YW50a"+
        "XR5ANAHAAAAAAAAAAAA";
    var buffer = Convert.FromBase64String(st);

    while (true)
    {
        var sp = Stopwatch.StartNew();
        for (int i = 0; i < 1024; i++)
        {
            DoWork(buffer);
        }
        Console.WriteLine(sp.ElapsedMilliseconds);
    }
}

private static void DoWork(byte[] buffer)
{
    var ms = new MemoryStream(buffer);
    JObject.Load(new BsonReader(ms));
    JObject.Load(new BsonReader(ms));
}

On my machine, this run at around 70ms for each 1,204 run. In other words, it takes significantly less I would have thought. Roughly 0.06 ms.

Note: The first number (0.4 ms) is under the profiler while the second number (0.06ms) is outside the profiler. You can routinely see order of magnitude differences between running inside and outside the profiler!

So far, so good, but we can literally see that this is adding almost a 100 ms to the request processing. That is good, because it is fairly simple to fix.

What I did was introduce a cache inside the serialization pipeline that made the entire cost go away. Indeed, running the same code above showed much better performance, an average of 200 ms.

The next step is to figure out where is the next cost factor… For that, we use the profiler.

And… we can see the the cost of de-serializing went drastically down. Now the actual cost is just doing a search for the document by the key.

You might have noticed that those results are for Munin. I have run the same test results with Esent, with remarkable similarity in the overall performance.

Originally posted at 1/17/2011

Occasionally I get asked what code review tools I use.

The truth is, I tend to use TortoiseGit’s Log Viewer and just read the history, but I am not leaning toward this baby:

This is really nice!

It wasn’t planned so much as it happened, but RavenMQ just slipped into private beta stage. The API is still in a the somewhat clumsy state, but it it is working quite nicely

You can see an example of the client API below:

using(var connection = RavenMQConnection.Connect("http://reduction:8181"))
{
    connection.Subscribe("/queues/abc", (context, message) => 
        Console.WriteLine(Encoding.UTF8.GetString(message.Data)));

    connection.PublishAsync(new IncomingMessage
    {
        Queue = "/queues/abc",
        Data = Encoding.UTF8.GetBytes("Hello Ravens")
    });

    Console.ReadLine();
}

Please note that this is likely to be subject to many changes.

This is written about 10 minutes after I posted the code above:

using(var connection = RavenMQConnection.Connect("http://localhost:8181"))
{
    connection.
        Subscribe<User>("/queues/abc", (context, message) => Console.WriteLine(message.Name));

    connection
        .StartPublishing
        .Add("/queues/abc", new User {Name = "Ayende"})
        .PublishAsync();

    Console.ReadLine();
}

I told you it would change…

Originally posted at 1/13/2011

You can find the recording here:

http://vimeo.com/18708232

After finally managing to get to Inbox Zero, I had the chance to tackle some problems that were on the back burner. One of the more acute ones was RavenDB performance for map/reduce indexes.

Standard indexes are actually very fast, especially since I just gave them an additional boost, but map/reduce indexes had two problems:

• The reduce operation is currently single threaded (for all indexes).
• The reduce operation blocks standard indexing.

In order to avoid that, we split the work so reduce would run in a separate thread from standard indexing operations. That done, I started to take a look at the actual cost of map/reduce operations.

It quickly became apparent that while the map part was pretty fast, it was the reduce operation that was killing us.

After some narrowing down, I was able to figure out that this is the code at fault:

public override void Execute(WorkContext context)
{
        if (ReduceKeys.Length == 0)
            return;

  var viewGenerator = context.IndexDefinitionStorage.GetViewGenerator(Index);
  if (viewGenerator == null)
    return; // deleted view?

  context.TransactionaStorage.Batch(actions =>
  {
    IEnumerable<object> mappedResults = null;
    foreach (var reduceKey in ReduceKeys)
    {
      IEnumerable<object> enumerable = actions.MappedResults.GetMappedResults(Index, reduceKey, MapReduceIndex.ComputeHash(Index, reduceKey))
        .Select(JsonToExpando.Convert);

      if (mappedResults == null)
        mappedResults = enumerable;
      else
        mappedResults = mappedResults.Concat(enumerable);
    }

    context.IndexStorage.Reduce(Index, viewGenerator, mappedResults, context, actions, ReduceKeys);
  });
}

Can you see the problem?

My first thought was that we had a problem with the code inside the foreach, since it effectively generate something like:

select * from MappedResulsts where Index = "MapReduceTestIndex" and ReduceKey = "Oren"
select * from MappedResulsts where Index = "MapReduceTestIndex" and ReduceKey = "Ayende"
select * from MappedResulsts where Index = "MapReduceTestIndex" and ReduceKey = "Arava"

And usually you’ll have about 2,500 of those.

Indeed, I modified the code to look like this:

public override void Execute(WorkContext context)
{
        if (ReduceKeys.Length == 0)
            return;

  var viewGenerator = context.IndexDefinitionStorage.GetViewGenerator(Index);
  if (viewGenerator == null)
    return; // deleted view?
  
  context.TransactionaStorage.Batch(actions =>
  {
    IEnumerable<object> mappedResults = new object[0];
    foreach (var reduceKey in ReduceKeys)
    {
      IEnumerable<object> enumerable = actions.MappedResults.GetMappedResults(Index, reduceKey, MapReduceIndex.ComputeHash(Index, reduceKey))
        .Select(JsonToExpando.Convert);

      mappedResults = mappedResults.Concat(enumerable);
    }
    var sp = Stopwatch.StartNew();
    Console.WriteLine("Starting to read {0} reduce keys", ReduceKeys.Length);

    var results = mappedResults.ToArray();

    Console.WriteLine("Read {0} reduce keys in {1} with {2} results", ReduceKeys.Length, sp.Elapsed, results.Length);

    context.IndexStorage.Reduce(Index, viewGenerator, results, context, actions, ReduceKeys);
  });
}

And got the following:

Starting to read 2470 reduce keys
Read 2470 reduce keys in 00:57:57.5292856 with 2499 results

Yes, for 2,470 results, that took almost an hour!!

I started planning how to fix this by moving to what is effectively an “IN” approach, when I realized that I skipped a very important step, I didn’t run this through the profiler. And as we know, if it haven’t run through the profiler, it isn’t real, when we are talking about performance testing.

And the profiler led me to this method:

public IEnumerable<JObject> GetMappedResults(string view, string reduceKey, byte[] viewAndReduceKeyHashed)
{
    Api.JetSetCurrentIndex(session, MappedResults, "by_reduce_key_and_view_hashed");
    Api.MakeKey(session, MappedResults, viewAndReduceKeyHashed, MakeKeyGrbit.NewKey);
    if (Api.TrySeek(session, MappedResults, SeekGrbit.SeekEQ) == false)
        yield break;


    Api.MakeKey(session, MappedResults, viewAndReduceKeyHashed, MakeKeyGrbit.NewKey);
    Api.JetSetIndexRange(session, MappedResults, SetIndexRangeGrbit.RangeUpperLimit | SetIndexRangeGrbit.RangeInclusive);
    if (Api.TryMoveFirst(session, MappedResults) == false)
        yield break;
    do
    {
        // we need to check that we don't have hash collisions
        var currentReduceKey = Api.RetrieveColumnAsString(session, MappedResults, tableColumnsCache.MappedResultsColumns["reduce_key"]);
        if (currentReduceKey != reduceKey)
            continue;
        var currentView = Api.RetrieveColumnAsString(session, MappedResults, tableColumnsCache.MappedResultsColumns["view"]);
        if (currentView != view)
            continue;
        yield return Api.RetrieveColumn(session, MappedResults, tableColumnsCache.MappedResultsColumns["data"]).ToJObject();
    } while (Api.TryMoveNext(session, MappedResults));
}

You might have noticed the part that stand out , yes, we actually had a O(n) algorithm here (effectively a table scan) that was absolutely meaningless and didn’t need to be there. I am pretty sure that it was test code that I wrote (yes, I run git blame on that and ordered some crow for tomorrow’s lunch).

Once I removed that, things changed for the better . To give you an idea how much, take a look at the new results:

Starting to read 2470 reduce keys
Read 2470 reduce keys in 00:00:00.4907501 with 2499 results

And just for fun, I had tested how long it takes to reduce each batch of results:

Indexed 2470 reduce keys in 00:00:01.0533390 with 2499 results

And that is without doing any actual optimizations, that is just removing the brain-dead code that had no business being there.

We are currently building the RavenDB Siliverlight Client, and along the way we run into several problems. Some of them were solved, but others proved to be much harder to deal with.

In particular, it seems that the way Silverlight handle HTTP caching is absolutely broken. In particular, Silverlight aggressively caches HTTP requests (which is good & proper), but the problem is that it ignores just about any of the cache control mechanisms that the HTTP spec specifies.

Note: I am talking specifically about the Client HTTP stack, the Browser HTTP stack behaves properly.

Here is the server code:

static void Main()
{
    var listener = new HttpListener();
    listener.Prefixes.Add("http://+:8080/");
    listener.Start();

    int reqNum = 0;
    while (true)
    {
        var ctx = listener.GetContext();

        Console.WriteLine("Req #{0}", reqNum);

        if(ctx.Request.Headers["If-None-Match"] == "1234")
        {
            ctx.Response.StatusCode = 304;
            ctx.Response.StatusDescription = "Not Modified";
            ctx.Response.Close();
            continue;
        }

        ctx.Response.Headers["ETag"] = "1234";
        ctx.Response.ContentType = "text/plain";
        using(var writer = new StreamWriter(ctx.Response.OutputStream))
        {
            writer.WriteLine(++reqNum);
            writer.Flush();
        }
        ctx.Response.Close();
    }
}

This is a pretty simple implementation, let us see how it behaves when we access the server from Internet Explorer (after clearing the cache):

The first request will hit the server to get the data, but the second request will ask the server if the cached data is fresh enough, and use the cache when we get the 304 reply.

So far, so good. And as expected, when we see the presence of an ETag in the request.

Let us see how this behaves with an Out of Browser Silverlight application (running with elevated security):

public partial class MainPage : UserControl
{
    public MainPage()
    {
        InitializeComponent();
    }

    private void StartRequest(object sender, RoutedEventArgs routedEventArgs)
    {
        var webRequest = WebRequestCreator.ClientHttp.Create(new Uri("http://ipv4.fiddler:8080"));

        webRequest.BeginGetResponse(Callback, webRequest);
    }

    private void Callback(IAsyncResult ar)
    {
        var webRequest = (WebRequest) ar.AsyncState;
        var response = webRequest.EndGetResponse(ar);

        var messageBoxText = new StreamReader(response.GetResponseStream()).ReadToEnd();
        Dispatcher.BeginInvoke(() => MessageBox.Show(messageBoxText));
    }
}

The StartRequest method is wired to a button click on the window.

Before starting, I cleared the IE cache again. Then I started the SL application and hit the button twice. Here is the output from fiddler:

Do you notice what you are not seeing here? That is right, there is no second request to the server to verify that the resource has not been changed.

Well, I thought to myself, that might be annoying behavior, but we can fix that, all we need to do is to specify must-revalidate in the Cache-Control. And so I did just that:

Do you see Silverlight pissing all over the HTTP spec? The only aspect of Cache-Control that the ClientHttp stack in Silverlight seems to respect is no-cache, which completely ignores etags.

As it turns out, there is one way of doing this. You need to send an Expires header in the past as well as an ETag header. The Expires header will force Silverlight to make the request again, and the ETag will be used to re-validate the request, resulting in a 304 reply from the server, which will load the data from the cache.

The fact that there is a workaround doesn’t mean it is not a bug, and it is a pretty severe one, making it much harder to write proper REST clients in Silverlight.

Originally posted at 1/10/2011

This is the first time in I don’t know how long, months, closer to half a year!

It is 16:37, and I think that I’ll just leave the office before something else jumps at me.