ASP.NET Core middleware to measure request processing time

posted by Jeff | Monday, May 30, 2016, 11:37 AM | comments: 0

One of the things that ASP.NET Core promises is a faster, streamlined processing pipeline. Naturally, you start to wonder how fast your pages render before being spit out into the tubes. With the fantastic ability to chain middleware in the pipeline (think HttpModules and HttpHandlers, only without the bazillion events), it's super easy to wrap most of the processing in a timer.

In high level terms, a request comes into the app and it is then "seen" by whatever middleware you have configured in the Startup class. If you've fired up a new project, you've already seen some of the included middleware configured in the Configure method using extension methods like app.UseMvc(), for example. These helper methods are likely calling something like app.UseMiddleware<T>(), where T is some type that includes an Invoke() method to do stuff, and a delegate to hand off processing to the next middleware. (This is all well documented, so I won't get deep here.)

It makes sense, then, that you can create your own middleware, and register it first in Configure to capture the time it takes for the entire process. Even better, you can do it inline without having to create a class for this simple output. It goes like this in the Startup class:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
	app.Use(async (context, next) =>
	{
		var sw = new Stopwatch();
		sw.Start();
		await next.Invoke();
		sw.Stop();
		await context.Response.WriteAsync(String.Format("<!-- {0} ms -->", sw.ElapsedMilliseconds));
	});

	// all the other middlware configured here, including UseStaticFiles() and UseMvc()

Hopefully that's straight forward. Each middleware calls the next, so while they execute in order up until they reach those next calls, they execute in reverse order after that for any code that falls after the next call in each middleware. The important part here is that it injects a comment at the end of the stream with the number of milliseconds it took to execute the rest of the middleware pipeline, which likely includes all of the MVC bits. So with that in mind, a few caveats:

  • This is not well tested. I can see it write out some (really fast) execution times on pages, but I'm not aware of any unintended consequences.
  • I would rather write to the headers collection, but unfortunately it's read-only by the time the last line fires. I'm sure someone more clever than me can figure out a way to do this.
  • I'm not sure what the consequences of doing this are on non-HTML output. I don't see the time being appended to static files, for example, but I'm not sure what it does to images that are streamed out from the MVC framework, for example (i.e., images taken from a database blob and written out from an action method).
  • This doesn't measure whatever overhead is involved in creating and managing the pipeline itself. I haven't looked very deeply into this to know what's going on, but as the point for ASP.NET Core is to ditch a lot of the crusties that came with old ASP.NET, I imagine it's not significant.

Have fun, and if you have ideas about how to improve this, do let me know!


Comments


Post your comment: