Skip to main content

Why not to use StopWatch when you need to measure the duration of an HTTP request in WebAPI

In this post we will talk about how we can measure how long it takes for a HTTP request to be executed on an ASP.NET MVC application.
All the tests are done using a web site hosted on Microsoft Azure. The instance used for this purpose is Shared - F1.

Let's assume that we have the following requirement:
At the end of each HTTP request you need to add to the logs information related to request duration.
The first solution that could come into our mind is to use "HttpContext.Current.Timestamp" to calculate the duration of a request. In theory we could calculate the difference between "DateTime.Now" and timestamp from "HttpContext".

protected void Application_EndRequest()
{
    Trace.WriteLine(string.Format("Request duration: {0}",
         (DateTime.Now - HttpContext.Current.Timestamp).TotalMilliseconds));
}

As we can see in the above example, we added this logic in the "Global.asax" file, in the "Application_EndRequest" method. Don't forget that the time format of HttpContext is local time not UTC time.

Out of topic: The code can be added in different locations, from "ActionFilter" to a HTTP Module. The location it is not important for now.

This solution is simple and nice, but the accurate of the duration is not the best one, but it is enough for most cases.
Remarks: Don't forget that "DateTime.Now" has a resolution accuracy of ~10ms.
But, the results are very good.
where:
  • min, avg and max is in ms
  • first table describes the status code of the http request
  • second table group all results based on request duration (first columns is request duration, second column contains the number of requests) 
For this, you could try to use Stopwatch and come with the following solution:
 
private static readonly ConcurrentDictionary<HttpRequest, Stopwatch> timeDictionary = 
     new ConcurrentDictionary<HttpRequest, Stopwatch>();

protected void Application_BeginRequest(object sender, EventArgs e)
{
    timeDictionary.TryAdd(
        Request, 
        Stopwatch.StartNew());
}

protected void Application_EndRequest(object sender, EventArgs e)
{
    Stopwatch sw = null;
    if (timeDictionary.TryGetValue(Request, out sw))
    {
        Trace.WriteLine(string.Format(
            "Request duration: {0}",
            sw.Elapsed));
    }
}

The above solution is using a Stopwatch to calculate the duration of each request. It will work great until ... you will hit 100 or 1.000 request per second. In that moment, if you have for example a Web API with a simple GET, like in the below example you will have 25s latency and a lot of timeouts.

[HttpGet]
public async Task<IHttpActionResult> GetFooAsync(string id)
{
    return Ok();
}

Results for 1.000 requests simultaneous:

You are wondering what are the results when you remove the logic from Begin and End requests. Let's take a look.
As we can see, without stopwatch we are pretty okay.
In comparison with the first test, that used "HttpContext.Current.Timestamp" the results are similar - +/- 1s is acceptable because the client was on my machine and the quality of internet connection can vary.

Le'ts try to not store the Stopwatch in a collection. We could add Stopwatch directly to the HttpRequest.

protected void Application_BeginRequest(object sender, EventArgs e)
{
    HttpApplication httpApp = (HttpApplication)sender;
    httpApp.Context.Items["Timer"] = Stopwatch.StartNew();
    ...
}


protected void Application_EndRequest(object sender, EventArgs e)
{
    var httpApp = (HttpApplication)sender;
    var sw = (Stopwatch)httpApp.Context.Items["Timer"];
    ...
}

The results are very similar with the one that we obtained using a collection of Stopwatch's.

  • min: 107ms     
  • avg: 25098.356ms     
  • max: 50489
The best solution
Of course the best solution is to use Performance Counters or a profiling tool like Glimse or similar tools. 

In conclusion we can say that using Stopwatch is a big mistake when we need to measure how long it takes for different block of code to execute when the load on the system is very high, especially on web application where we can use HttpContext.

Comments

Popular posts from this blog

How to check in AngularJS if a service was register or not

There are cases when you need to check in a service or a controller was register in AngularJS.
For example a valid use case is when you have the same implementation running on multiple application. In this case, you may want to intercept the HTTP provider and add a custom step there. This step don’t needs to run on all the application, only in the one where the service exist and register.
A solution for this case would be to have a flag in the configuration that specify this. In the core you would have an IF that would check the value of this flag.
Another solution is to check if a specific service was register in AngularJS or not. If the service was register that you would execute your own logic.
To check if a service was register or not in AngularJS container you need to call the ‘has’ method of ‘inhector’. It will return TRUE if the service was register.
if ($injector.has('httpInterceptorService')) { $httpProvider.interceptors.push('httpInterceptorService&#…

ADO.NET provider with invariant name 'System.Data.SqlClient' could not be loaded

Today blog post will be started with the following error when running DB tests on the CI machine:
threw exception: System.InvalidOperationException: The Entity Framework provider type 'System.Data.Entity.SqlServer.SqlProviderServices, EntityFramework.SqlServer' registered in the application config file for the ADO.NET provider with invariant name 'System.Data.SqlClient' could not be loaded. Make sure that the assembly-qualified name is used and that the assembly is available to the running application. See http://go.microsoft.com/fwlink/?LinkId=260882 for more information. at System.Data.Entity.Infrastructure.DependencyResolution.ProviderServicesFactory.GetInstance(String providerTypeName, String providerInvariantName) This error happened only on the Continuous Integration machine. On the devs machines, everything has fine. The classic problem – on my machine it’s working. The CI has the following configuration:

TeamCity.NET 4.51EF 6.0.2VS2013
It seems that there …

[Post-Event] Codecamp Conference Cluj-Napoca - Nov 19, 2016

Last day I was invited to another Codecamp Conference, that took place in Cluj-Napoca. Like other Codecamp Conferences, the event was very big, with more than 1.000 participants and 70 sessions. There were 10 tracks in parallel, so it was pretty hard to decide at  what session you want to join.
It was great to join this conference and I hope that you discovered something new during the conference.
At this event I talked about Azure IoT Hub and how we can use it to connect devices from the field. I had a lot of demos using Raspberry PI 3 and Simplelink SensorTag. Most of the samples were written in C++ and Node.JS and people were impressed that even if we are using Microsoft technologies, we are not limited to C# and .NET. World and Microsoft are changing so fast. Just looking and Azure IoT Hub and new features that were launched and I'm pressed (Jobs, Methods, Device Twin).
On backend my demos covered Stream Analytics, Event Hub, Azure Object Storage and DocumentDB.

Title:
What abo…