Code Sample: TimeMeasure in AspNetCore MVC


In the recent article, Code Sample: TimeMeasureTest, I showed how to perform time measuring related operations with the static TimeMeasure class. Moving to ASP.NET Core MVC, I have included two ways to perform the same operation on your Controller methods; one by using TimeMeasureAttribute explicitly or by using a TimeMeasuringFilter in general.

The former approach is great if you suspect a method to be slow and just want a simple way to time measure the code; the latter is for more instrumentation minded usage, where you might setup a threshold and store the result for application insight.

Instrumentation

Common for both approaches is, that somewhere in your configuration (most likely the Startup class) you assign a callback method to the TimeMeasure.CompletedCallback delegate. I simply used a lamda expression: profiler => Trace.WriteLine(profiler.ToString());

The first example uses the TimeMeasureAttribute approach. You simply decorate one or more methods that you want insights for. Optionally, you can configure the attribute with a threshold. For instance, if you only want to trigger a callback when a method takes longer than 1 second, you would decorate the attribute like this: [TimeMeasure(1, TimeUnit.Seconds)].

using System;  
using Cuemon.AspNetCore.Mvc;  
using Cuemon.AspNetCore.Mvc.Filters;  
using Cuemon.Integrity;  
using Microsoft.AspNetCore.Mvc;

namespace Cuemon.Core.Examples  
{
    public class TimeSpanController : Controller
    {
        [TimeMeasure]
        [HttpHead]
        [HttpGet]
        [Route("{hours}/{minutes}/{seconds}")]
        public IActionResult GetTimeSpan(int hours, int minutes, int seconds)
        {
            return this.OkOrNotModified(new TimeSpan(hours, minutes, seconds), ts => CacheValidator.ReferencePoint.CombineWith(ts.Ticks));
        }
    }
}

When the method is called 5 times, it produces this result:

TimeMesaureAttribute Result

The other example is the general approach, and for simplicity I only included what isolated needs to be done in the ConfigureServices method. Optionally you can provide an options delegate that has three properties; TimeMeasureCompletedThreshold, MethodDescriptor and RuntimeParameters. The most important is the TimeMeasureCompletedThreshold. The other two are for advanced scenarios.

using Cuemon.AspNetCore.Mvc.Filters;  
using Microsoft.Extensions.DependencyInjection;

namespace Cuemon.Core.Examples  
{
    public class Startup
    {
        public void ConfigureServices(IServiceCollection services)
        {
            services.AddMvc(o => o.Filters.Add(new TimeMeasuringFilter()));
        }
    }
}

Thats it .. same result as the first example, but will cover all controller related methods using ActionExecutingContext.

As always; I hope you have enjoyed reading this article - HAPPY CODING!

Code Sample: PartitionCollectionTest


About 3 years ago, I posted an article about Too much to digest? Slice it up in chunks!, which worked, but was a rather complex way of slicing items into smaller bites.

Fruit

For a while now, there has been an alternative; the PartitionCollection<T> class in the Cuemon.Collections.Generic namespace. Depending on your .NET installation, there are also extension methods ToPartitionCollection that might come in handy.

The usage is simple, as illustrated here (i have kept the example as close to the original as possible):

using System.Diagnostics;  
using System.Linq;  
using Cuemon.Collections.Generic;  
using Microsoft.VisualStudio.TestTools.UnitTesting;

namespace Cuemon.Examples  
{
    [TestClass]
    public class PartitionCollectionTest
    {
        [TestMethod]
        public void ChunkTest()
        {
            var workload = 4096;
            var partitionSize = 255;
            var simulatedWorkload = Enumerable.Range(0, workload).ToPartitionCollection(partitionSize);

            Trace.WriteLine("Work to process: {0} items.".FormatWith(workload));
            Trace.WriteLine("Partitions for work: {0} runs.".FormatWith(simulatedWorkload.PartitionCount()));

            while (simulatedWorkload.HasPartitions)
            {
                var chunkedWorkload = simulatedWorkload.ToList();
                foreach (var work in chunkedWorkload)
                {
                    // process your work here
                }
                
                Trace.WriteLine("Remaining work to process: {0} items.".FormatWith(simulatedWorkload.Remaining));
            }
        }
    }
}
The result is well familiar:
Work to process: 4096 items.  
Partitions for work: 17 runs.  
Remaining work to process: 3841 items.  
Remaining work to process: 3586 items.  
Remaining work to process: 3331 items.  
Remaining work to process: 3076 items.  
Remaining work to process: 2821 items.  
Remaining work to process: 2566 items.  
Remaining work to process: 2311 items.  
Remaining work to process: 2056 items.  
Remaining work to process: 1801 items.  
Remaining work to process: 1546 items.  
Remaining work to process: 1291 items.  
Remaining work to process: 1036 items.  
Remaining work to process: 781 items.  
Remaining work to process: 526 items.  
Remaining work to process: 271 items.  
Remaining work to process: 16 items.  
Remaining work to process: 0 items.  

As always; I hope you found these small articles inspiring - and happy coding!

Code Sample: TimeMeasureTest


Every now and then you have to time measure different parts of your system. One approach could be a simple StopWatch or even different DateTime objects subtracted one another. My approach, as with TransientOperation, is to provide a lamda friendly way of performing this task.

Instrumentation

Any measurement can be performed simply by calling one of the overloaded methods on the static TimeMeasure class; WithAction or WithFunc. The latter will contain a property holding the Result of the operation.

As with most of the "instrumentation" in this framework, you can easily attach a callback method to TimeMeasure.CompletedCallback and hereby get valuable information/statistic for your liking.

I hope this little introduction will help simplify your time measurement related operations. Happy coding!

using System;  
using System.Diagnostics;  
using System.Net;  
using System.Threading;  
using Cuemon.Diagnostics;  
using Cuemon.Net.Http;  
using Microsoft.VisualStudio.TestTools.UnitTesting;

namespace Cuemon.Examples  
{
    [TestClass]
    public class TimeMeasureTest
    {
        [TestMethod]
        public void AggregateTimeMeasurementTest()
        {
            var websiteProfiler = TimeMeasure.WithFunc(GetWebpageBodySize, new Uri("https://www.cuemon.net/";));
            Trace.WriteLine("Body size: {0} KB.".FormatWith(websiteProfiler.Result.BytesToKilobytes()));
            Trace.WriteLine("");
            Trace.WriteLine(websiteProfiler);
            var profiler = TimeMeasure.WithAction(MethodThatTakesBetweenOneToFiveSeconds);
            Trace.WriteLine(profiler);
            profiler = TimeMeasure.WithAction(MethodThatTakesBetweenFiveToTwentySeconds);
            Trace.WriteLine(profiler);
            profiler = TimeMeasure.WithAction(MethodWithRandomParameters, false42"flexible"Guid.Empty, 666.666m);
            Trace.WriteLine(profiler);
        }

        public long GetWebpageBodySize(Uri location)
        {
            return location.HttpGet(o => o.AutomaticDecompression = DecompressionMethods.None).ContentLength;
        }

        public void MethodThatTakesBetweenOneToFiveSeconds()
        {
            Thread.Sleep(TimeSpan.FromSeconds(NumberUtility.GetRandomNumber(16)));
        }

        public void MethodThatTakesBetweenFiveToTwentySeconds()
        {
            Thread.Sleep(TimeSpan.FromSeconds(NumberUtility.GetRandomNumber(521)));
        }

        public void MethodWithRandomParameters(bool a, int b, string c, Guid d, decimal e)
        {
            // do nothing
        }
    }
}
Notice the ClassName.MemberName(Parameters) followed by the actual elapsed time and the values of the Paramters (if any).
Body size: 31.3037109375 KB.

TimeMeasureTest.GetWebpageBodySize(Uri location) took 00:00:00.482019300 to execute. Parameters: { location=https://www.cuemon.net/ }  
TimeMeasureTest.MethodThatTakesBetweenOneToFiveSeconds() took 00:00:04.019125500 to execute.  
TimeMeasureTest.MethodThatTakesBetweenFiveToTwentySeconds() took 00:00:08.001355400 to execute.  
TimeMeasureTest.MethodWithRandomParameters(Boolean a, Int32 b, String c, Guid d, Decimal e) took 00:00:00.001324900 to execute. Parameters: { a=False, b=42, c=flexible, d=00000000-0000-0000-0000-000000000000, e=666,666 }  

Code Sample: TransientOperationTest


So, its been a while since my last post on this blog. About 3 and half year ago, I posted an article about The dark side of the Cloud; network connectivity issues and service unavailability, and although the problem remains, the code behind this feature has changed. A lot.

retry-and-wait

So bringing forth today is a revised example of protecting a HttpHead operation. In this example, I was pointing to https://www.cuemon.net:111/, where I deliberately changed the port to 111 just to force a transient exception.

Any operation can be protected simply by calling one of the overloaded methods on the static TransientOperation class; WithAction, WithFunc or TryWithFunc.

Because this test was written for the .NET Framework, you will notice an exception of ThreadException. In the .NET Platform Standard edition, this would be an AggregateException being thrown.

Common for both editions are, that they will have one inner exception of TransientFaultException should the exception be transient related (options.DetectionStrategy delegate).

For this sample, I am currently marking two exception types; TimeoutException and WebException as transient related exceptions. Should any of these be present in the exception parameter of the DetectionStrategy delegate, the retry logic will be triggered.

With the forthcoming release, you will notice (if you pay close attention) that I have included details about the exception directly on the TransientFaultException class. Before, the information was appended to the Data property, but now a new property has been introduced; Evidence.

Here is the result of these new features:

Cuemon.TransientFaultException: The amount of retry attempts has been reached. NetHttpUtilityExtensions.HttpHead(Uri location) was invoked 5 time(s) over a period of 00:00:36.0418522. Last recovery wait time was 00:00:16, giving a total recovery wait time of 00:00:31. Latency was 00:00:05.0418522.

A quick breakdown shows, that the retry-logic was invoked 5 times over a period of 36 seconds. The total retry wait time was 31 seconds. That leaves 5 seconds latency. The latency in this case is a result of me tweaking the NetHttpUtility.DefaultHttpTimeout to 1 second. Otherwise, latency would have been around 150 seconds.

Any operation can be protected simply by calling one of the overloaded methods on the static TransientOperation class; WithAction, WithFunc or TryWithFunc.

As with most of the "instrumentation" in this framework, you can easily attach a callback method to TransientOperation.FaultCallback and hereby get valuable information/statistic for your liking.

That should be about it. I hope you can see a value in the code sample provided; happy coding!

using System;  
using System.Diagnostics;  
using System.Net;  
using Cuemon.Net.Http;  
using Microsoft.VisualStudio.TestTools.UnitTesting;

namespace Cuemon.Examples  
{
    [TestClass]
    public class TransientOperationTest
    {
        [TestMethod]
        public void OpenWebsiteTest()
        {
            try
            {
                var website = new Uri("https://www.cuemon.net/");
                var response = TransientOperation.WithFunc(website.HttpHead, options =>
                {
                    options.DetectionStrategy = exception =>
                    {
                        var timeoutException = exception.ParseException<TimeoutException>();
                        var webException = exception.ParseException<WebException>();
                        return (webException != null|| (timeoutException != null);
                    };
                });

                Trace.Write(response.Headers.ToString());
            }
            catch (Exception e)
            {
                Console.WriteLine(e);
                throw;
            }

        }
    }
}
Notice the total of 6 exceptions; the first exception was before the retry-logic was triggered. The following 5 exceptions was because of the retry-logic.
Cuemon.Threading.ThreadException: One or more errors occurred.  
   at Cuemon.TransientOperation.WithFuncCore[TTuple,TResult](DoerFactory`2 factory, Act`1 setup) in ---
   at Cuemon.TransientOperation.WithFunc[TResult](Doer`1 faultSensitiveMethod, Act`1 setup) in ---
   at Cuemon.Examples.TransientOperationTest.OpenWebsiteTest() in ---
 --> (Inner exception 0) Cuemon.TransientFaultException: The amount of retry attempts has been reached. NetHttpUtilityExtensions.HttpHead(Uri location) was invoked 5 time(s) over a period of 00:00:36.0418522. Last recovery wait time was 00:00:16, giving a total recovery wait time of 00:00:31. Latency was 00:00:05.0418522.

 --> (Inner exception 1) System.ArgumentException: An error occurred while invoking the asynchronous operation.
Parameter name: request ---> System.TimeoutException: The HTTP request https://www.cuemon.net:111/ took longer than the specified timeout value of 00:00:01.  
   at Cuemon.Net.Http.NetHttpUtility.WebResponseFromAsync(Doer`3 beginMethod, Doer`2 endMethod, HttpWebRequest state) in ---
   --- End of inner exception stack trace ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(HttpWebRequest request) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(Uri location, String method, Stream content, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.Http(String method, Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location) in ---
   at Cuemon.Net.Http.NetHttpUtilityExtensions.HttpHead(Uri location)
   at Cuemon.DoerFactory.<>c__DisplayClass0_0`1.<Create>b__0(Template tuple) in ---
   at Cuemon.DoerFactory`2.ExecuteMethod() in ---
   at Cuemon.TransientOperation.WithFuncCore[TTuple,TResult](DoerFactory`2 factory, Act`1 setup) in ---

 --> (Inner exception 2) System.ArgumentException: An error occurred while invoking the asynchronous operation.
Parameter name: request ---> System.TimeoutException: The HTTP request https://www.cuemon.net:111/ took longer than the specified timeout value of 00:00:01.  
   at Cuemon.Net.Http.NetHttpUtility.WebResponseFromAsync(Doer`3 beginMethod, Doer`2 endMethod, HttpWebRequest state) in ---
   --- End of inner exception stack trace ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(HttpWebRequest request) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(Uri location, String method, Stream content, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.Http(String method, Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location) in ---
   at Cuemon.Net.Http.NetHttpUtilityExtensions.HttpHead(Uri location)
   at Cuemon.DoerFactory.<>c__DisplayClass0_0`1.<Create>b__0(Template tuple) in ---
   at Cuemon.DoerFactory`2.ExecuteMethod() in ---
   at Cuemon.TransientOperation.WithFuncCore[TTuple,TResult](DoerFactory`2 factory, Act`1 setup) in ---

 --> (Inner exception 3) System.ArgumentException: An error occurred while invoking the asynchronous operation.
Parameter name: request ---> System.TimeoutException: The HTTP request https://www.cuemon.net:111/ took longer than the specified timeout value of 00:00:01.  
   at Cuemon.Net.Http.NetHttpUtility.WebResponseFromAsync(Doer`3 beginMethod, Doer`2 endMethod, HttpWebRequest state) in ---
   --- End of inner exception stack trace ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(HttpWebRequest request) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(Uri location, String method, Stream content, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.Http(String method, Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location) in ---
   at Cuemon.Net.Http.NetHttpUtilityExtensions.HttpHead(Uri location)
   at Cuemon.DoerFactory.<>c__DisplayClass0_0`1.<Create>b__0(Template tuple) in ---
   at Cuemon.DoerFactory`2.ExecuteMethod() in ---
   at Cuemon.TransientOperation.WithFuncCore[TTuple,TResult](DoerFactory`2 factory, Act`1 setup) in ---

 --> (Inner exception 4) System.ArgumentException: An error occurred while invoking the asynchronous operation.
Parameter name: request ---> System.TimeoutException: The HTTP request https://www.cuemon.net:111/ took longer than the specified timeout value of 00:00:01.  
   at Cuemon.Net.Http.NetHttpUtility.WebResponseFromAsync(Doer`3 beginMethod, Doer`2 endMethod, HttpWebRequest state) in ---
   --- End of inner exception stack trace ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(HttpWebRequest request) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(Uri location, String method, Stream content, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.Http(String method, Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location) in ---
   at Cuemon.Net.Http.NetHttpUtilityExtensions.HttpHead(Uri location)
   at Cuemon.DoerFactory.<>c__DisplayClass0_0`1.<Create>b__0(Template tuple) in ---
   at Cuemon.DoerFactory`2.ExecuteMethod() in ---
   at Cuemon.TransientOperation.WithFuncCore[TTuple,TResult](DoerFactory`2 factory, Act`1 setup) in ---

 --> (Inner exception 5) System.ArgumentException: An error occurred while invoking the asynchronous operation.
Parameter name: request ---> System.TimeoutException: The HTTP request https://www.cuemon.net:111/ took longer than the specified timeout value of 00:00:01.  
   at Cuemon.Net.Http.NetHttpUtility.WebResponseFromAsync(Doer`3 beginMethod, Doer`2 endMethod, HttpWebRequest state) in ---
   --- End of inner exception stack trace ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(HttpWebRequest request) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(Uri location, String method, Stream content, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.Http(String method, Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location) in ---
   at Cuemon.Net.Http.NetHttpUtilityExtensions.HttpHead(Uri location)
   at Cuemon.DoerFactory.<>c__DisplayClass0_0`1.<Create>b__0(Template tuple) in ---
   at Cuemon.DoerFactory`2.ExecuteMethod() in ---   at Cuemon.TransientOperation.WithFuncCore[TTuple,TResult](DoerFactory`2 factory, Act`1 setup) in ---

 --> (Inner exception 6) System.ArgumentException: An error occurred while invoking the asynchronous operation.
Parameter name: request ---> System.TimeoutException: The HTTP request https://www.cuemon.net:111/ took longer than the specified timeout value of 00:00:01.  
   at Cuemon.Net.Http.NetHttpUtility.WebResponseFromAsync(Doer`3 beginMethod, Doer`2 endMethod, HttpWebRequest state) in ---
   --- End of inner exception stack trace ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(HttpWebRequest request) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpCore(Uri location, String method, Stream content, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.Http(String method, Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location, Act`1 setup) in ---
   at Cuemon.Net.Http.NetHttpUtility.HttpHead(Uri location) in ---
   at Cuemon.Net.Http.NetHttpUtilityExtensions.HttpHead(Uri location)
   at Cuemon.DoerFactory.<>c__DisplayClass0_0`1.<Create>b__0(Template tuple) in ---
   at Cuemon.DoerFactory`2.ExecuteMethod() in ---
   at Cuemon.TransientOperation.WithFuncCore[TTuple,TResult](DoerFactory`2 factory, Act`1 setup) in ---