This is probably true for any kind of software, but web sites and services need to be fast. People don’t like watching “spinners” on their browser while they wait for a page to load or a button to do something. When spinners happen, people get upset. In some cases, the delay might constitute an incident, a violation of your service level agreement (SLA). That’s the world I live in. If something takes longer than 4 seconds, I hear about it. And if it happens more than a couple of times, I have to figure out what is going on.

That’s where metrics come to save the day. Every service has performance instrumentation on the entry points, not just for the whole method but for all the steps in the method. All those metrics get logged, so if I need to see how a method was performing, I can pull them and get instant answers to how long things were taking. The output could be something like:

 HiPerfMetric 'HomeController.Index' running time - .510406 seconds
-----------------------------------------
 ms        % Task name
-----------------------------------------
  7.934  2 % Validate Inputs 
499.203 97 % Get Content 
  3.269  1 % Assemble model

This tells me that the call to the Index method of the HomeController (the default page) is taking half a second in the controller, and that 97% of that time is spent getting content. Yes, we use CMS, but it shouldn’t take half a second to call that service. At this point, I would look for the content service’s metrics and try to further troubleshoot the half second call. I’m not going to bore you with those details now because, hopefully, you are skilled in the ways of troubleshooting. The important part of this article is the code we use to get the metrics.

We have been using a piece of code from a Code Project article, HiPerfTimer, but we needed it to do more. The report above is our own invention. We’d also like other reports, like a series of log messages, or streaming to an xml file, and more. To do that, we needed another project. So I created HiPerfMetrics. It has the same license as HiPerfTimer and contains the same original source file. But we added code for collecting related timers and reporting on them, as seen above.

The new class, HiPerfMetric, stores a list of timers and a total time for all the timers. And the default report gives an output like the one above. Usage is fairly simple: create a metric, start and stop timers on it, then report. This is an example from one of the tests:

    var metric = new HiPerfMetric("NormalTwoTaskReport");
    metric.Start("task 1");
    Thread.Sleep(250);
    metric.Stop();
    metric.Start("task 2");
    Thread.Sleep(500);
    metric.Stop();
    var report = new DefaultReport
    {
        Metric = metric
    };
    Debug.WriteLine(report.Report());

That’s pretty much it. I’ve put it up on Nuget as HiPerfMetrics, so feel free to get the nuget and use it. If you feel like making HiPerfMetrics better, shoot me a message and we’ll see. I have a wish list and I’m willing to listen to other people’s ideas, too.

Check the github project for my wishlist.