Merge pull request #2091 from jaroslavbliznak/feature/2046-measuremen…

…t-of-execution-time FIX-2046 Measurement of execution time of method
equinor · Oct 17, 2023 · 4d4a29f · 4d4a29f
2 parents 20d8657 + c3f1013
commit 4d4a29f
Show file tree

Hide file tree

Showing 4 changed files with 116 additions and 67 deletions.
diff --git a/Src/Witsml/Helpers/MeasurementHelper.cs b/Src/Witsml/Helpers/MeasurementHelper.cs
@@ -0,0 +1,57 @@
+using System;
+using System.Diagnostics;
+using System.Linq;
+using System.Threading.Tasks;
+
+using Serilog;
+
+namespace Witsml.Helpers;
+
+/// <summary>
+/// The class allows customization of the message for execution time logging.
+/// </summary>
+public class TimeMeasurer
+{
+    /// <summary>
+    /// Gets or sets a delegate that takes an elapsed time in milliseconds and returns a log message.
+    /// </summary>
+    public Func<long, string> LogMessage { get; set; }
+}
+
+/// <summary>
+/// Measures execution time of code and logging.
+/// </summary>
+public static class MeasurementHelper
+{
+    private const int MeasuredMethodNameStackTraceFrameDepth = 5;
+
+    /// <summary>
+    /// Measures the execution time of an asynchronous operation and provides the ability to customize the logging message.
+    /// </summary>
+    /// <param name="measureCode">A delegate representing the asynchronous operation to be measured.</param>
+    /// <typeparam name="TResult">The type of result returned by the asynchronous operation.</typeparam>
+    /// <returns>An asynchronous task that represents the result of the measured operation.</returns>
+    public static async Task<TResult> MeasureExecutionTimeAsync<TResult>(Func<TimeMeasurer, Task<TResult>> measureCode)
+    {
+        var timeMeasurer = new TimeMeasurer();
+        var stopwatch = new Stopwatch();
+        var measuredMethodName = new StackTrace().GetFrames().Skip(MeasuredMethodNameStackTraceFrameDepth).FirstOrDefault()?.GetMethod()?.Name;
+
+        stopwatch.Start();
+
+        TResult result = await measureCode(timeMeasurer);
+
+        stopwatch.Stop();
+
+        if (timeMeasurer.LogMessage != null)
+        {
+            Log.Debug(timeMeasurer.LogMessage(stopwatch.ElapsedMilliseconds));
+        }
+        else
+        {
+            Log.Debug("The execution of the method '{MeasuredMethodName}' finished in {ElapsedMilliseconds}ms.", measuredMethodName, stopwatch.ElapsedMilliseconds);
+        }
+
+        return result;
+    }
+}
diff --git a/Src/WitsmlExplorer.Api/Services/MessageObjectService.cs b/Src/WitsmlExplorer.Api/Services/MessageObjectService.cs
@@ -1,11 +1,9 @@
-using System;
 using System.Collections.Generic;
 using System.Linq;
 using System.Threading.Tasks;
 
-using Serilog;
-
 using Witsml.Data;
+using Witsml.Helpers;
 using Witsml.ServiceReference;
 
 using WitsmlExplorer.Api.Models;
@@ -35,14 +33,16 @@ public async Task<MessageObject> GetMessageObject(string wellUid, string wellbor
 
         public async Task<IEnumerable<MessageObject>> GetMessageObjects(string wellUid, string wellboreUid)
         {
-            DateTime start = DateTime.Now;
-            WitsmlMessages witsmlMessage = MessageQueries.GetMessageByWellbore(wellUid, wellboreUid);
-            WitsmlMessages result = await _witsmlClient.GetFromStoreAsync(witsmlMessage, new OptionsIn(ReturnElements.Requested));
-            List<MessageObject> messageObjects = result.Messages
-                .Select(FromWitsml).OrderBy((m) => m.DTim).ToList();
-            double elapsed = DateTime.Now.Subtract(start).Milliseconds / 1000.0;
-            Log.Debug("Fetched {Count} messageobjects from {WellboreName} in {Elapsed} seconds", messageObjects.Count, messageObjects.FirstOrDefault()?.WellboreName, elapsed);
-            return messageObjects;
+            return await MeasurementHelper.MeasureExecutionTimeAsync(async (timeMeasurer) =>
+            {
+                WitsmlMessages witsmlMessage = MessageQueries.GetMessageByWellbore(wellUid, wellboreUid);
+                WitsmlMessages result = await _witsmlClient.GetFromStoreAsync(witsmlMessage, new OptionsIn(ReturnElements.Requested));
+                List<MessageObject> messageObjects = result.Messages
+                    .Select(FromWitsml).OrderBy((m) => m.DTim).ToList();
+                timeMeasurer.LogMessage = executionTime =>
+                    $"Fetched {messageObjects.Count} messageObjects from {messageObjects.FirstOrDefault()?.WellboreName} in {executionTime}ms.";
+                return messageObjects;
+            });
         }
 
         private static MessageObject FromWitsml(WitsmlMessage message)

diff --git a/Src/WitsmlExplorer.Api/Services/WellService.cs b/Src/WitsmlExplorer.Api/Services/WellService.cs
@@ -1,13 +1,9 @@
-using System;
-using System.Collections;
 using System.Collections.Generic;
-using System.Diagnostics;
 using System.Linq;
 using System.Threading.Tasks;
 
-using Serilog;
-
 using Witsml.Data;
+using Witsml.Helpers;
 using Witsml.ServiceReference;
 
 using WitsmlExplorer.Api.Models;
@@ -48,30 +44,30 @@ public async Task<IList<Well>> GetWells()
 
         private async Task<IList<Well>> GetWellsInformation(string wellUid = null)
         {
-            var stopwatch = new Stopwatch();
-            stopwatch.Start();
-            WitsmlWells witsmlWells = string.IsNullOrEmpty(wellUid) ? WellQueries.GetAllWitsmlWells() : WellQueries.GetWitsmlWellByUid(wellUid);
-            WitsmlWells result = await _witsmlClient.GetFromStoreAsync(witsmlWells, new OptionsIn(ReturnElements.Requested));
-            List<Well> wells = result.Wells
-                .Select(well => new Well
-                {
-                    Uid = well.Uid,
-                    Name = well.Name,
-                    Field = well.Field,
-                    Operator = well.Operator,
-                    NumLicense = well.NumLicense,
-                    TimeZone = well.TimeZone,
-                    DateTimeCreation = well.CommonData.DTimCreation,
-                    DateTimeLastChange = well.CommonData.DTimLastChange,
-                    ItemState = well.CommonData.ItemState,
-                    StatusWell = well.StatusWell,
-                    PurposeWell = well.PurposeWell,
-                    Country = well.Country
-                }
-                ).ToList();
-            stopwatch.Stop();
-            Log.Debug("Fetched {Count} wells in {Elapsed} ms", wells.Count, stopwatch.ElapsedMilliseconds);
-            return wells;
+            return await MeasurementHelper.MeasureExecutionTimeAsync(async (timeMeasurer) =>
+            {
+                WitsmlWells witsmlWells = string.IsNullOrEmpty(wellUid) ? WellQueries.GetAllWitsmlWells() : WellQueries.GetWitsmlWellByUid(wellUid);
+                WitsmlWells result = await _witsmlClient.GetFromStoreAsync(witsmlWells, new OptionsIn(ReturnElements.Requested));
+                List<Well> wells = result.Wells
+                    .Select(well => new Well
+                        {
+                            Uid = well.Uid,
+                            Name = well.Name,
+                            Field = well.Field,
+                            Operator = well.Operator,
+                            NumLicense = well.NumLicense,
+                            TimeZone = well.TimeZone,
+                            DateTimeCreation = well.CommonData.DTimCreation,
+                            DateTimeLastChange = well.CommonData.DTimLastChange,
+                            ItemState = well.CommonData.ItemState,
+                            StatusWell = well.StatusWell,
+                            PurposeWell = well.PurposeWell,
+                            Country = well.Country
+                        }
+                    ).ToList();
+                timeMeasurer.LogMessage = executionTime => $"Fetched {wells.Count} wells in {executionTime} ms.";
+                return wells;
+            });
         }
 
         public async Task<Well> GetWell(string wellUid)

diff --git a/Src/WitsmlExplorer.Api/Services/WellboreService.cs b/Src/WitsmlExplorer.Api/Services/WellboreService.cs
@@ -1,12 +1,9 @@
-using System;
 using System.Collections.Generic;
-using System.Diagnostics;
 using System.Linq;
 using System.Threading.Tasks;
 
-using Serilog;
-
 using Witsml.Data;
+using Witsml.Helpers;
 using Witsml.ServiceReference;
 
 using WitsmlExplorer.Api.Models;
@@ -68,29 +65,28 @@ public async Task<Wellbore> GetWellbore(string wellUid, string wellboreUid)
 
         public async Task<IList<Wellbore>> GetWellbores(string wellUid = "")
         {
-            var stopwatch = new Stopwatch();
-            stopwatch.Start();
-            WitsmlWellbores query = WellboreQueries.GetWitsmlWellboreByWell(wellUid);
-
-            WitsmlWellbores result = await _witsmlClient.GetFromStoreAsync(query, new OptionsIn(ReturnElements.Requested));
-            List<Wellbore> wellbores = result.Wellbores
-                .Select(witsmlWellbore =>
-                    new Wellbore
-                    {
-                        Uid = witsmlWellbore.Uid,
-                        Name = witsmlWellbore.Name,
-                        WellUid = witsmlWellbore.UidWell,
-                        WellName = witsmlWellbore.NameWell,
-                        WellStatus = witsmlWellbore.StatusWellbore,
-                        WellType = witsmlWellbore.TypeWellbore,
-                        IsActive = StringHelpers.ToBooleanSafe(witsmlWellbore.IsActive),
-                        DateTimeLastChange = witsmlWellbore.CommonData.DTimLastChange,
-                        DateTimeCreation = witsmlWellbore.CommonData.DTimCreation
-                    })
-                .OrderBy(wellbore => wellbore.Name).ToList();
-            stopwatch.Stop();
-            Log.Debug("Fetched {Count} wellbores in {Elapsed} ms", wellbores.Count, stopwatch.ElapsedMilliseconds);
-            return wellbores;
+            return await MeasurementHelper.MeasureExecutionTimeAsync(async (timeMeasurer) =>
+            {
+                WitsmlWellbores query = WellboreQueries.GetWitsmlWellboreByWell(wellUid);
+                WitsmlWellbores result = await _witsmlClient.GetFromStoreAsync(query, new OptionsIn(ReturnElements.Requested));
+                List<Wellbore> wellbores = result.Wellbores
+                    .Select(witsmlWellbore =>
+                        new Wellbore
+                        {
+                            Uid = witsmlWellbore.Uid,
+                            Name = witsmlWellbore.Name,
+                            WellUid = witsmlWellbore.UidWell,
+                            WellName = witsmlWellbore.NameWell,
+                            WellStatus = witsmlWellbore.StatusWellbore,
+                            WellType = witsmlWellbore.TypeWellbore,
+                            IsActive = StringHelpers.ToBooleanSafe(witsmlWellbore.IsActive),
+                            DateTimeLastChange = witsmlWellbore.CommonData.DTimLastChange,
+                            DateTimeCreation = witsmlWellbore.CommonData.DTimCreation
+                        })
+                    .OrderBy(wellbore => wellbore.Name).ToList();
+                timeMeasurer.LogMessage = executionTime => $"Fetched {wellbores.Count} wellbores in {executionTime} ms.";
+                return wellbores;
+            });
         }
     }
 }