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

Windows Docker Containers can make WIN32 API calls, use COM and ASP.NET WebForms

After the last post , I received two interesting questions related to Docker and Windows. People were interested if we do Win32 API calls from a Docker container and if there is support for COM. WIN32 Support To test calls to WIN32 API, let’s try to populate SYSTEM_INFO class. [StructLayout(LayoutKind.Sequential)] public struct SYSTEM_INFO { public uint dwOemId; public uint dwPageSize; public uint lpMinimumApplicationAddress; public uint lpMaximumApplicationAddress; public uint dwActiveProcessorMask; public uint dwNumberOfProcessors; public uint dwProcessorType; public uint dwAllocationGranularity; public uint dwProcessorLevel; public uint dwProcessorRevision; } ... [DllImport("kernel32")] static extern void GetSystemInfo(ref SYSTEM_INFO pSI); ... SYSTEM_INFO pSI = new SYSTEM_INFO(

Azure AD and AWS Cognito side-by-side

In the last few weeks, I was involved in multiple opportunities on Microsoft Azure and Amazon, where we had to analyse AWS Cognito, Azure AD and other solutions that are available on the market. I decided to consolidate in one post all features and differences that I identified for both of them that we should need to take into account. Take into account that Azure AD is an identity and access management services well integrated with Microsoft stack. In comparison, AWS Cognito is just a user sign-up, sign-in and access control and nothing more. The focus is not on the main features, is more on small things that can make a difference when you want to decide where we want to store and manage our users.  This information might be useful in the future when we need to decide where we want to keep and manage our users.  Feature Azure AD (B2C, B2C) AWS Cognito Access token lifetime Default 1h – the value is configurable 1h – cannot be modified

What to do when you hit the throughput limits of Azure Storage (Blobs)

In this post we will talk about how we can detect when we hit a throughput limit of Azure Storage and what we can do in that moment. Context If we take a look on Scalability Targets of Azure Storage ( https://azure.microsoft.com/en-us/documentation/articles/storage-scalability-targets/ ) we will observe that the limits are prety high. But, based on our business logic we can end up at this limits. If you create a system that is hitted by a high number of device, you can hit easily the total number of requests rate that can be done on a Storage Account. This limits on Azure is 20.000 IOPS (entities or messages per second) where (and this is very important) the size of the request is 1KB. Normally, if you make a load tests where 20.000 clients will hit different blobs storages from the same Azure Storage Account, this limits can be reached. How we can detect this problem? From client, we can detect that this limits was reached based on the HTTP error code that is returned by HTTP