The cost of routing

time to read 8 min | 1565 words

I was asked to see what is the cost of WebAPI on Kestrel, and it lines up nicely with a topic that I wanted to talk about, routing. So I thought I’ll start with a small benchmark.

Here is a small Kestrel based server, using MVC / WebAPI:

public class Program
{
    public void ConfigureServices(IServiceCollection services)
    {
        services.AddMvc();
    }

    public void Configure(IApplicationBuilder app, ILoggerFactory loggerfactory)
    {
        app.UseMvc();
    }

    public static void Main(string[] args)
    {
        var configBuilder = new ConfigurationBuilder()
            .Add(new MemoryConfigurationProvider(new Dictionary<string, string>
            {
                ["server.urls"] = "http://localhost:8080"
            }));

        IHostingEngine application = new WebHostBuilder(configBuilder.Build())
            .UseStartup<Program>()
            .UseServer("Microsoft.AspNet.Server.Kestrel")
            .Build();


        using (application.Start())
        {
            Console.WriteLine("ready");
            Console.ReadLine();
        }
    }
}

And here is a simple controller:

[Route("api/[controller]")]
public class ValuesController : Controller
{
    // GET api/values
    [HttpGet()]
    public string Get()
    {
        return "Hello World";
    }
}

As you can see, this couldn’t really be any more trivial. I have tested this with release mode, using the following gobench command:

.\gobench.exe -c 100 -r 25000 -u http://localhost:8080/api/values

This was run after running a couple thousand requests as warm up.  In other words, we are going to do a 2.5 million requests. I intentionally choose that value, because it force the server to do enough work to be meaningful, and the test run is long enough to see other factors creeping in. Note that this isn’t a “real” benchmark, both gobench and this code are actually running on the same machine. But it is a good baseline.

Requests:                          2,500,000 hits
Successful requests:               2,500,000 hits
Network failed:                            0 hits
Bad requests failed (!2xx):                0 hits
Successful requests rate:             56,818 hits/sec
Read throughput:                   9,261,363 bytes/sec
Write throughput:                  5,454,545 bytes/sec
Test time:                                44 sec

Those are good numbers. Now let us see that with my code:

[RavenAction("/api/values", "GET")]
public Task ValuesGet()
{
    return HttpContext.Response.WriteAsync("Hello world");
}

There is no funny business here. We just route the request using my code, and then just write it to the client. The results:

Requests:                          2,500,000 hits
Successful requests:               2,500,000 hits
Network failed:                            0 hits
Bad requests failed (!2xx):                0 hits
Successful requests rate:             86,206 hits/sec
Read throughput:                  10,517,241 bytes/sec
Write throughput:                  8,275,862 bytes/sec
Test time:                                29 sec

That is over 25% improvement.

Now, there are a couple of things that works out better for my code. To start with, it is calling Response.WriteAsync directly, while the standard WebAPI code needs to get the result, figure out how to write it, etc.

In the profiler, this looks really interesting:

image

So the time for actually executing the action is less than 10% of the request time. Everything else is some sort of setup.

In fact, let us dig deeper, the time to run our action is 0.2% of the 10% that this method runs:

image

To be fair, the method just returns a constant string. I would be shocked if it wasn’t really fast.

Most of the time happens in the CreateActionResult, in which we select how we write. Let us look at this a bit differently:

image

The InvokeExceptionFilterAsync is the part responsible for actually calling our code and getting the result.

The InvokeAllResultFiltersAsync is responsible for figuring out how to write the output to the client. And this is the part where we actually write to the network:

image

And here is how we do in the same scenario:

image

You can note that 85% of the time we are spending in servicing the request, with just 15% dedicated to managing the infrastructure.

I’ll discuss the details of that in my next post, though.