Scripting and Profiling Improvements in StackExchange.Redis

At Stack Exchange, we make pretty heavy use of Redis.  We’re so invested we’ve had our best minds build not one, but two different .NET libraries for it.  Recent(ish) experience with the Providence project has prompted additions to the modern library, StackExchange.Redis, in the realms of Lua scripting and Profiling.

Lua Scripting Improvements

StackExchange.Redis already had full support for Redis’s scripting commands when Providence started, but Lua scripting wasn’t really used at StackExchange at that time.  Early versions of Providence started making extensive use of Lua scripts to make atomic updates to our data during our daily refresh process, and we started having painful experiences.  The root cause of our pain was that Redis requires you write your script using KEYS and ARGV arrays to pass parameters.

Here’s a toy example to illustrate the issue.  The command

eval "redis.call('set', KEYS[1], ARGV[1])" 1 theKey 1 theArg

rendered in C# as

IDatabase db = /* ... */
var theKey = /* ... */
var theArg = /* ... */
db.ScriptEvaluate(
  "redis.call('set', KEYS[1], ARGV[1])",
  new RedisKey[] { theKey },
  new RedisValue [] { theArg }
);

sets one “the-key” to “the-arg”.  The actual script in your source would be “redis.call(‘set’, KEYS[1], ARGV[1])” which is… less than ideal, especially once your scripts start getting complicated.

In recent versions of StackExchange.Redis there’s an alternative, use the new LuaScript class.  This lets you refer to variables by name in a manner inspired by Dapper (the Stack Exchange micro-ORM).

The previous example would now be rendered in C# as:

IDatabase db = /* ... */
var theKey = /* ... */
var theArg = /* ... */
var script = LuaScript.Prepare("redis.call('set', @theKey, @theArg)");
db.ScriptEvaluate(script, new { theKey, theArg });

LuaScript rewrites your script to refer to ARGV and also handles mapping your parameters to the appropriate ARGV index (and places any parameters of type RedisKey into the KEYS array as well, so as to play nicely with Redis Cluster).  You can use any object to specify parameters, so long as it has a public field or property for each @parameter.

To avoid the overhead of transmitting the script text for every call to IDatabase.ScriptEvaluate, you can convert a LuaScript into a LoadedLuaScript like so:

IServer server = /* ... */
LuaScript script = /* ... */
LoadedLuaScript loaded = server.ScriptLoad(script);

The LoadedLuaScript class provides the same functionality as the LuaScript class, but uses the SCRIPT LOAD and EVALSHA commands to avoid re-transmitting the entire script when evaluated.

Profiling Improvements

While Redis is really (really really) fast, at Stack Overflow we’ve still been profiling its impact on page load times since time immemorial.  Everytime a developer looks at Stack Overflow, they get informed of how much time was spent in talking to Redis.

That 48.8ms includes a fair amount of “moderator only” work too.

The way Stack Overflow uses Redis is analogous to how we use SQL Server – send query, wait for it to complete, read the response, then proceed.  StackExchange.Redis multiplexes and pipelines so the application doesn’t block waiting for responses, but individual HTTP requests do as a consequence of their logic.

Accordingly, Stack Overflow’s Redis profiling code has been conceptually:

var watch = Stopwatch.StartNew();
IDatabase db = /* ... */
db.GetString(/* ... */);
watch.Stop();
PushToProfilingStats(watch.Elapsed);

Obviously the actual code is more sophisticated.

Providence, however, works quite differently.  For each request to Providence, it dispatches several Redis commands and then combines them once they all finish.

In other words, the Providence Redis code tends to look like:

IDatabase db = /* ... */
var inFlight =
  new List<Task>
  {
    GatherFooFieldsAsync(),  // does an async redis query or two
    GatherBarFieldsAsync()   // likewise
    /* and so on */
  };
 await Task.WhenAll(inFlight);

To better support profiling in situations like Providence’s, StackExchange.Redis now has the IProfiler interface,  the RegisterProfiler method, the BeginProfiling method, and the FinishProfiling method.  These new additions are used by StackExchange.Redis to associate dispatched commands with a user provided context object, even when using the async and await keywords.

Exactly how to determine context is application specific but the following code is used in the Providence API project, which is a stock MVC5 website.

// The IProfiler implementation
public class RedisProfiler : IProfiler
{
    const string RequestContextKey = "RequestProfilingContext";

    public object GetContext()
    {
        var ctx = HttpContext.Current;
        if (ctx == null) return null;

        return ctx.Items[RequestContextKey];
    }

    public object CreateContextForCurrentRequest()
    {
        var ctx = HttpContext.Current;
        if (ctx == null) return null;

        object ret;
        ctx.Items[RequestContextKey] = ret = new object();

        return ret;
    }
}

// In Global.asax.cs
static RedisProfiler RedisProfiler;
static ConnectionMultiplexer RedisConnection;

protected void Application_Start()
{
    RedisProfiler = new RedisProfiler();
    RedisConnection = ConnectionMultiplexer.Connect(...);
    RedisConnection.RegisterProfiler(RedisProfiler);
    // and actual app startup logic ...
}

protected void Application_BeginRequest()
{
    var ctxObj = RedisProfiler.CreateContextForCurrentRequest();
    if (ctxObj != null)
    {
      RedisConnection.BeginProfiling(ctxObj);
    }

    // and actual per-request logic ...
}

protected void Application_EndRequest()
{
    var ctxObj = RedisProfiler.GetContext();
    if (ctxObj != null)
    {
        var timings = RedisConnection.FinishProfiling(ctxObj);

        var totalCommands = 0;
        double totalMilliseconds = 0;

        foreach (var timing in timings)
        {
            totalCommands++;
            totalMilliseconds += timing.ElapsedTime.TotalMilliseconds;
        }

        // and then perf recording logic ...
    }

    // and actual end of request logic ...
}

More examples of profiling with different notions of context can be found in the StackExchange.Redis profiling tests.

Profiling provides details on each command dispatched, not just their count and time to execute.  Timings are exposed as IProfiledCommands, which includes information about:

• The Redis instance the command was sent to
• The DB the command was run in
• The command itself
• Any CommandFlags specified
• When the command was created, which corresponds to when the StackExchange.Redis method was called
• How long it took to enqueue the command after it was created
• How long it took to send the command after it was enqueued
• How long it took Redis to respond after the command was sent
• How long it took to process the response after it was received
• Total time elapsed from command creation til the response was processed
• If the command was a retransmission due to Redis Cluster
• If the command was a retransmitted, a reference to the original commands timings
• If the command was a retransmission, whether it was an ASK or MOVED that prompted it

StackExchange.Redis is available on GitHub and NuGet