BookSleeve - Poor Performance When Setting Hashes

I'm in the process of updating my web service to use the latest BookSleeve library, 1.3.38. Previously I was using 1.1.0.7

While doing some benchmarking, I noticed that setting hashes in Redis using the new version of BookSleeve is many times slower than the old version. Please consider the following C# benchmarking code:

public void TestRedisHashes()
{
  int numItems = 1000; // number of hash items to set in redis 
  int numFields = 30; // number of fields in each redis hash
  RedisConnection redis = new RedisConnection("10.0.0.01", 6379);
  redis.Open();

  // wait until the connection is open
  while (!redis.State.Equals(BookSleeve.RedisConnectionBase.ConnectionState.Open)) { }

  Stopwatch timer = new Stopwatch();
  timer.Start();
  for (int i = 0; i < numItems; i++)
  {
    string key = "test_" + i.ToString();

    for (int j = 0; j < numFields; j++)
    {
      // set a value for each field in the hash
      redis.Hashes.Set(0, key, "field_" + j.ToString(), "testdata");
    }
    redis.Keys.Expire(0, key, 30); // 30 second ttl
  }
  timer.Stop();

  Console.WriteLine("Elapsed time for hash writes: {0} ms", timer.ElapsedMilliseconds);
}

BookSleeve 1.1.0.7 takes about 20ms to set 1000 hashes to Redis 2.6, while 1.3.38 takes around 400ms. That's 20X slower! Everything other part of BookSleeve 1.3.38 that I've tested is either as fast or faster than the old version. I've also tried the same test using Redis 2.4 as well as wrapping everything in a transaction. In both cases I got similar performance.

Has anyone else noticed anything like this? I must be doing something wrong... am I setting hashes correctly using the new version of BookSleeve? Is this the right way to do fire-and-forget commands? I've looked though the unit tests as an example of how to use hashes, but haven't been able to find what I'm doing differently. Is it possible that the newest version is just slower in this case?

Solution

To actually test the overall speed you would need to add code that waits for the last of the messages to be processed, for example:

  Task last = null;
  for (int i = 0; i < numItems; i++)
  {
    string key = "test_" + i.ToString();

    for (int j = 0; j < numFields; j++)
    {
      // set a value for each field in the hash
      redis.Hashes.Set(0, key, "field_" + j.ToString(), "testdata");
    }
    last = redis.Keys.Expire(0, key, 30); // 30 second ttl
  }
  redis.Wait(last);

Otherwise all you are timing is how fast the call to Set/Expire is. And in this case, that could matter. You see, in 1.1.0.7, all messages are immediately placed onto a queue, and a separate dedicated writer thread then picks up that message and writes it to the stream. In 1.3.38, the dedicated writer thread is gone (for various reasons). So if the socket is available, the calling thread writes to the underlying stream (if the socket is in use, there is a mechanism to handle that). More importantly, it is possible that in your original test against 1.1.0.7, no useful work has actually happened yet - there is no guarantee that work is anywhere near the socket, etc.

In most scenarios, this does not cause any overhead (and is less overhead when amortized), however: it is possible that in your case you are being impacted by effectively buffer under-run - in 1.1.0.7 you would have filled the buffer really quickly, and the worker thread would have probably always found more waiting messages - so it would not flush the stream until the end; in 1.3.38, it is probably flushing between messages. So: let's fix that:

Task last = null;
redis.SuspendFlush();
try {
  for (int i = 0; i < numItems; i++)
  {
    string key = "test_" + i.ToString();

    for (int j = 0; j < numFields; j++)
    {
      // set a value for each field in the hash
      redis.Hashes.Set(0, key, "field_" + j.ToString(), "testdata");
    }
    last = redis.Keys.Expire(0, key, 30); // 30 second ttl
  }
}
finally {
  redis.ResumeFlush();
}
redis.Wait(last);

The SuspendFlush() / ResumeFlush() pair is ideal when calling a large batch of operations on a single thread to avoid any additional flushing. To copy the intellisense notes:

//
// Summary:
// Temporarily suspends eager-flushing (flushing if the write-queue becomes
// empty briefly). Buffer-based flushing will still occur when the data is full.
// This is useful if you are performing a large number of operations in close
// duration, and want to avoid packet fragmentation. Note that you MUST call
// ResumeFlush at the end of the operation - preferably using Try/Finally so
// that flushing is resumed even upon error. This method is thread-safe; any
// number of callers can suspend/resume flushing concurrently - eager flushing
// will resume fully when all callers have called ResumeFlush.
//
// Remarks:
// Note that some operations (transaction conditions, etc) require flushing
// - this will still occur even if the buffer is only part full.

Note that in most high throughput scenarios there are multiple operations coming in from multiple threads: in those scenarios, any work from concurrent threads will automatically be queued in a way that minimises the number of threads.