Added options to exclude time spent in external libraries

Author: Bart Koelman

src/JsonApiDotNetCore/Diagnostics/CascadingCodeTimer.cs

@@ -33,22 +33,23 @@ static CascadingCodeTimer()
             Thread.CurrentThread.Priority = ThreadPriority.Highest;
         }
 
-        public IDisposable Measure(string name)
+        /// <inheritdoc />
+        public IDisposable Measure(string name, bool excludeInRelativeCost = false)
         {
-            MeasureScope childScope = CreateChildScope(name);
+            MeasureScope childScope = CreateChildScope(name, excludeInRelativeCost);
             _activeScopeStack.Push(childScope);
 
             return childScope;
         }
 
-        private MeasureScope CreateChildScope(string name)
+        private MeasureScope CreateChildScope(string name, bool excludeInRelativeCost)
         {
             if (_activeScopeStack.TryPeek(out MeasureScope topScope))
             {
-                return topScope.SpawnChild(this, name);
+                return topScope.SpawnChild(this, name, excludeInRelativeCost);
             }
 
-            return new MeasureScope(this, name);
+            return new MeasureScope(this, name, excludeInRelativeCost);
         }
 
         private void Close(MeasureScope scope)
@@ -66,6 +67,7 @@ private void Close(MeasureScope scope)
             }
         }
 
+        /// <inheritdoc />
         public string GetResult()
         {
             var builder = new StringBuilder();
@@ -99,14 +101,16 @@ private sealed class MeasureScope : IDisposable
         {
             private readonly CascadingCodeTimer _owner;
             private readonly IList<MeasureScope> _children = new List<MeasureScope>();
+            private readonly bool _excludeInRelativeCost;
             private readonly TimeSpan _startedAt;
             private TimeSpan? _stoppedAt;
 
             public string Name { get; }
 
-            public MeasureScope(CascadingCodeTimer owner, string name)
+            public MeasureScope(CascadingCodeTimer owner, string name, bool excludeInRelativeCost)
             {
                 _owner = owner;
+                _excludeInRelativeCost = excludeInRelativeCost;
                 Name = name;
 
                 EnsureRunning();
@@ -121,9 +125,9 @@ private void EnsureRunning()
                 }
             }
 
-            public MeasureScope SpawnChild(CascadingCodeTimer owner, string name)
+            public MeasureScope SpawnChild(CascadingCodeTimer owner, string name, bool excludeInRelativeCost)
             {
-                var childScope = new MeasureScope(owner, name);
+                var childScope = new MeasureScope(owner, name, excludeInRelativeCost);
                 _children.Add(childScope);
                 return childScope;
             }
@@ -151,23 +155,47 @@ private TimeSpan GetElapsedInChildren()
                 return elapsedInChildren;
             }
 
+            private TimeSpan GetSkippedInTotal()
+            {
+                TimeSpan skippedInSelf = _excludeInRelativeCost ? GetElapsedInSelf() : TimeSpan.Zero;
+                TimeSpan skippedInChildren = GetSkippedInChildren();
+
+                return skippedInSelf + skippedInChildren;
+            }
+
+            private TimeSpan GetSkippedInChildren()
+            {
+                TimeSpan skippedInChildren = TimeSpan.Zero;
+
+                foreach (MeasureScope childScope in _children)
+                {
+                    skippedInChildren += childScope.GetSkippedInTotal();
+                }
+
+                return skippedInChildren;
+            }
+
             public void WriteResult(StringBuilder builder, int indent)
             {
-                TimeSpan timeElapsedGlobal = GetElapsedInTotal();
+                TimeSpan timeElapsedGlobal = GetElapsedInTotal() - GetSkippedInTotal();
                 WriteResult(builder, indent, timeElapsedGlobal);
             }
 
             private void WriteResult(StringBuilder builder, int indent, TimeSpan timeElapsedGlobal)
             {
                 TimeSpan timeElapsedInSelf = GetElapsedInSelf();
-                double scaleElapsedInSelf = timeElapsedInSelf / timeElapsedGlobal;
+                double scaleElapsedInSelf = timeElapsedGlobal != TimeSpan.Zero ? timeElapsedInSelf / timeElapsedGlobal : 0;
 
                 WriteIndent(builder, indent);
                 builder.Append(Name);
                 builder.Append(": ");
                 builder.Append(timeElapsedInSelf.ToString("G", CultureInfo.InvariantCulture));
-                builder.Append(" - ");
-                builder.Append(scaleElapsedInSelf.ToString("P", CultureInfo.InvariantCulture));
+
+                if (!_excludeInRelativeCost)
+                {
+                    builder.Append(" - ");
+                    builder.Append(scaleElapsedInSelf.ToString("P", CultureInfo.InvariantCulture));
+                }
 
                 if (_stoppedAt == null)
                 {

src/JsonApiDotNetCore/Diagnostics/ConsoleDemo.cs

@@ -1,5 +1,4 @@
 #if DEBUG
-
 using System;
 using System.Threading.Tasks;
 
@@ -72,5 +71,4 @@ private static async Task SerializeResponseAsync()
         }
     }
 }
-
 #endif

src/JsonApiDotNetCore/Diagnostics/DisabledCodeTimer.cs

@@ -15,7 +15,7 @@ private DisabledCodeTimer()
         {
         }
 
-        public IDisposable Measure(string name)
+        public IDisposable Measure(string name, bool excludeInRelativeCost = false)
         {
             return this;
         }

src/JsonApiDotNetCore/Diagnostics/ICodeTimer.cs

@@ -14,7 +14,10 @@ public interface ICodeTimer : IDisposable
         /// <param name="name">
         /// Description of what is being recorded.
         /// </param>
-        IDisposable Measure(string name);
+        /// <param name="excludeInRelativeCost">
+        /// When set, indicates to exclude this measurement in calculated percentages. <c>false</c> by default.
+        /// </param>
+        IDisposable Measure(string name, bool excludeInRelativeCost = false);
 
         /// <summary>
         /// Returns intermediate or final results.

src/JsonApiDotNetCore/Diagnostics/MeasurementConstants.cs

@@ -0,0 +1,10 @@
+#pragma warning disable AV1008 // Class should not be static
+
+namespace JsonApiDotNetCore.Diagnostics
+{
+    internal static class MeasurementConstants
+    {
+        public static readonly bool ExcludeEfCoreInPercentages = bool.Parse(bool.FalseString);
+        public static readonly bool ExcludeNewtonsoftJsonInPercentages = bool.Parse(bool.FalseString);
+    }
+}

src/JsonApiDotNetCore/Repositories/EntityFrameworkCoreRepository.cs

@@ -77,7 +77,7 @@ public virtual async Task<IReadOnlyCollection<TResource>> GetAsync(QueryLayer la
             {
                 IQueryable<TResource> query = ApplyQueryLayer(layer);
 
-                using (CodeTimingSessionManager.Current.Measure("Execute SQL (data)"))
+                using (CodeTimingSessionManager.Current.Measure("Execute SQL (data)", MeasurementConstants.ExcludeEfCoreInPercentages))
                 {
                     return await query.ToListAsync(cancellationToken);
                 }
@@ -103,7 +103,7 @@ public virtual async Task<int> CountAsync(FilterExpression topFilter, Cancellati
 
                 IQueryable<TResource> query = ApplyQueryLayer(layer);
 
-                using (CodeTimingSessionManager.Current.Measure("Execute SQL (count)"))
+                using (CodeTimingSessionManager.Current.Measure("Execute SQL (count)", MeasurementConstants.ExcludeEfCoreInPercentages))
                 {
                     return await query.CountAsync(cancellationToken);
                 }
@@ -563,7 +563,7 @@ protected virtual async Task SaveChangesAsync(CancellationToken cancellationToke
         {
             cancellationToken.ThrowIfCancellationRequested();
 
-            using (CodeTimingSessionManager.Current.Measure("Persist EF Core changes"))
+            using (CodeTimingSessionManager.Current.Measure("Persist EF Core changes", MeasurementConstants.ExcludeEfCoreInPercentages))
             {
                 try
                 {

src/JsonApiDotNetCore/Serialization/BaseDeserializer.cs

@@ -62,7 +62,7 @@ protected object DeserializeBody(string body)
         {
             ArgumentGuard.NotNullNorEmpty(body, nameof(body));
 
-            using (CodeTimingSessionManager.Current.Measure("Newtonsoft.Deserialize"))
+            using (CodeTimingSessionManager.Current.Measure("Newtonsoft.Deserialize", MeasurementConstants.ExcludeNewtonsoftJsonInPercentages))
             {
                 JToken bodyJToken = LoadJToken(body);
                 Document = bodyJToken.ToObject<Document>();

src/JsonApiDotNetCore/Serialization/BaseSerializer.cs

@@ -99,7 +99,7 @@ protected string SerializeObject(object value, JsonSerializerSettings defaultSet
         {
             ArgumentGuard.NotNull(defaultSettings, nameof(defaultSettings));
 
-            using (CodeTimingSessionManager.Current.Measure("Newtonsoft.Serialize"))
+            using (CodeTimingSessionManager.Current.Measure("Newtonsoft.Serialize", MeasurementConstants.ExcludeNewtonsoftJsonInPercentages))
             {
                 var serializer = JsonSerializer.CreateDefault(defaultSettings);
                 changeSerializer?.Invoke(serializer);

src/JsonApiDotNetCore/Serialization/RequestDeserializer.cs

@@ -79,7 +79,7 @@ private object DeserializeOperationsDocument(string body)
         {
             AtomicOperationsDocument document;
 
-            using (CodeTimingSessionManager.Current.Measure("Newtonsoft.Deserialize"))
+            using (CodeTimingSessionManager.Current.Measure("Newtonsoft.Deserialize", MeasurementConstants.ExcludeNewtonsoftJsonInPercentages))
             {
                 JToken bodyToken = LoadJToken(body);
                 document = bodyToken.ToObject<AtomicOperationsDocument>();