Addition of stats.processing.time for logging

Gigya.Microdot.Hosting/Events/StatsEvent.cs

@@ -23,6 +23,7 @@
 using System;
 using System.Collections.Generic;
 using System.Globalization;
+using System.Linq;
 using Gigya.Microdot.Interfaces.Events;
 using Gigya.Microdot.SharedLogic.Events;
 using Gigya.Microdot.SharedLogic.Measurement;
@@ -43,17 +44,22 @@ public IEnumerable<KeyValuePair<string, string>> UserStats
                 foreach (var value in Timings.Value.UserStats)
                 {
                     userMeasurements.Add(value.Key + ".count", value.Value.TotalInstances.ToString());
-                    userMeasurements.Add(value.Key + ".avgMs", (value.Value.TotalTime.TotalMilliseconds / value.Value.TotalInstances).ToString(CultureInfo.InvariantCulture));
+                    userMeasurements.Add(value.Key + ".avgMs",
+                        (value.Value.TotalTime.TotalMilliseconds / value.Value.TotalInstances).ToString(CultureInfo
+                            .InvariantCulture));
                 }
 
                 return userMeasurements;
             }
         }
 
 
-        [EventField(EventConsts.statsTotalTime, OmitFromAudit = true)]
+        [EventField("stats.total.time", OmitFromAudit = true)]
         public virtual double? TotalTime => Timings.Value.Request.ElapsedMS;
 
+        [EventField("stats.netprocessing.time", OmitFromAudit = true)]
+        public double? ProcessingTime => CalculateProcessingTime();
+
         [EventField("stats.mysql.time", OmitFromAudit = true)]
         public double? MySqlTime => Timings.Value.DataSource.MySql.Total.ElapsedMS;
 
@@ -155,7 +161,23 @@ public IEnumerable<KeyValuePair<string, string>> UserStats
         [EventField("stats.hades.deletes", OmitFromAudit = true)]
         public long? CallsHadesDelete => Timings.Value.DataSource.Hades.Delete.Calls;
 
+        private double? CalculateProcessingTime()
+        {
+            if (TotalTime == null)
+                return null;
 
+            double servicesTime = 0;
+            foreach (var serviceCall in Timings.Value.ServicesCallsDictionary.Values)
+            {
+                if (serviceCall.ElapsedMS != null)
+                    servicesTime += serviceCall.ElapsedMS.Value;
+            }
+
+            if (servicesTime == 0)
+                return null;
+
+            return TotalTime - servicesTime;
+        }
 
     }
 }

Gigya.Microdot.ServiceProxy/ServiceProxyProvider.cs

@@ -43,6 +43,7 @@
 using Gigya.Microdot.SharedLogic;
 using Gigya.Microdot.SharedLogic.Events;
 using Gigya.Microdot.SharedLogic.Exceptions;
+using Gigya.Microdot.SharedLogic.Measurement;
 using Gigya.Microdot.SharedLogic.Security;
 using Metrics;
 using Newtonsoft.Json;
@@ -370,15 +371,20 @@ private async Task<object> InvokeCore(HttpServiceRequest request, Type resultRet
                     httpContent.Headers.Add(GigyaHttpHeaders.Version, HttpServiceRequest.Version);
 
                     clientCallEvent.RequestStartTimestamp = Stopwatch.GetTimestamp();
-                    try
-                    {
-                        response = await GetHttpClient(config).PostAsync(uri, httpContent).ConfigureAwait(false);
-                        responseContent = await response.Content.ReadAsStringAsync().ConfigureAwait(false);
-                    }
-                    finally
+
+                    using (RequestTimings.Current.ServicesCallsDictionary[ServiceName].Measure())
                     {
-                        clientCallEvent.ResponseEndTimestamp = Stopwatch.GetTimestamp();
+                        try
+                        {
+                            response = await GetHttpClient(config).PostAsync(uri, httpContent).ConfigureAwait(false);
+                            responseContent = await response.Content.ReadAsStringAsync().ConfigureAwait(false);
+                        }
+                        finally
+                        {
+                            clientCallEvent.ResponseEndTimestamp = Stopwatch.GetTimestamp();
+                        }
                     }
+
                     if (response.Headers.TryGetValues(GigyaHttpHeaders.ExecutionTime, out IEnumerable<string> values))
                     {
                         var time = values.FirstOrDefault();

Gigya.Microdot.SharedLogic/Gigya.Microdot.SharedLogic.csproj

@@ -53,6 +53,7 @@
     <Compile Include="Exceptions\StackTraceEnhancer.cs" />
     <Compile Include="Exceptions\StripHttpRequestExceptionConverter.cs" />
     <Compile Include="Logging\LogBase.cs" />
+    <Compile Include="Measurement\ServicesCallsDictionary.cs" />
     <Compile Include="Monitor\AggregatingHealthStatus.cs" />
     <Compile Include="Monitor\IHealthMonitor.cs" />
     <Compile Include="PortOffsets.cs" />

Gigya.Microdot.SharedLogic/Measurement/RequestTimings.cs

@@ -30,10 +30,12 @@ namespace Gigya.Microdot.SharedLogic.Measurement
     /// various data sources (mysql, mongo, etc), the time it took to perform calls to providers, and the total time spent
     /// processing the current request.</summary>
     [Serializable]
-    public class RequestTimings:MarshalByRefObject
+    public class RequestTimings : MarshalByRefObject
     {
         internal readonly ConcurrentDictionary<string, Aggregator> UserStats = new ConcurrentDictionary<string, Aggregator>();
 
+        public ServicesCallsDictionary ServicesCallsDictionary = new ServicesCallsDictionary();
+
         /// <summary>Time of the ongoing request.</summary>
         public ConcurrentStopwatch Request = new ConcurrentStopwatch();
 
@@ -67,7 +69,5 @@ public static void ClearCurrentTimings()
         /// <summary>Starts measuring the top-level processing of the current request. Handy when it's inconvenient for you
         /// to call Request.Measure()</summary>
         public void MarkRequestStartTime() { Request.Start(); }
-
-
     }
 }

Gigya.Microdot.SharedLogic/Measurement/ServicesCallsDictionary.cs

@@ -0,0 +1,14 @@
+using System;
+using System.Collections.Concurrent;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+
+namespace Gigya.Microdot.SharedLogic.Measurement
+{    
+    public class ServicesCallsDictionary : ConcurrentDictionary<string, ConcurrentStopwatch>
+    {
+        public new ConcurrentStopwatch this[string serviceName] { get { return GetOrAdd(serviceName, x => new ConcurrentStopwatch()); } }
+    }
+}

SolutionVersion.cs

@@ -28,9 +28,9 @@
 [assembly: AssemblyCopyright("© 2018 Gigya Inc.")]
 [assembly: AssemblyDescription("Microdot Framework")]
 
-[assembly: AssemblyVersion("1.11.1.0")]
-[assembly: AssemblyFileVersion("1.11.1.0")] 
-[assembly: AssemblyInformationalVersion("1.11.1.0")]
+[assembly: AssemblyVersion("1.12.0.0")]
+[assembly: AssemblyFileVersion("1.12.0.0")] 
+[assembly: AssemblyInformationalVersion("1.12.0.0")]
 
 
 // Setting ComVisible to false makes the types in this assembly not visible 

tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs

@@ -0,0 +1,52 @@
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+using Gigya.Microdot.Hosting.Events;
+using Gigya.Microdot.SharedLogic.Events;
+using Gigya.Microdot.SharedLogic.Measurement;
+using NUnit.Framework;
+using FluentAssertions;
+using Shouldly;
+
+namespace Gigya.Microdot.UnitTests.Events
+{
+    public class StatsEventTests
+    {
+        [Test]
+        public async Task ProcessingTime_TotalTimeIsNull_Null()
+        {            
+            var statsEvent = new MockStatsEvent();            
+            statsEvent.ProcessingTime.ShouldBeNull();
+        }
+
+        [Test]
+        public async Task ProcessingTime_ServicesTimeIsNull_Null()
+        {
+            var statsEvent = new MockStatsEvent();
+            using (RequestTimings.Current.Request.Measure()) { }
+
+            statsEvent.ProcessingTime.ShouldBeNull();
+        }
+
+        [Test]
+        public async Task ProcessingTime_TotalTimeAndServicesTimeHaveValues_TotalTimeMinusServicesTime()
+        {
+            var statsEvent = new MockStatsEvent();
+            using (RequestTimings.Current.Request.Measure()) { }
+
+            using (RequestTimings.Current.ServicesCallsDictionary["Service1"].Measure()) {}
+            using (RequestTimings.Current.ServicesCallsDictionary["Service2"].Measure()) {}
+
+            var expected = RequestTimings.Current.Request.ElapsedMS - RequestTimings.Current.ServicesCallsDictionary["Service1"].ElapsedMS - RequestTimings.Current.ServicesCallsDictionary["Service2"].ElapsedMS;
+
+            statsEvent.ProcessingTime.Should().BeApproximately(expected.Value, 0.0001);
+        }
+    }
+
+    internal class MockStatsEvent : StatsEvent
+    {
+
+    }
+}

tests/Gigya.Microdot.UnitTests/Gigya.Microdot.UnitTests.csproj

@@ -63,6 +63,7 @@
     <Compile Include="Discovery\ServiceDiscoveryConfigChangeTest.cs" />
     <Compile Include="Discovery\ConsulDiscoveryMasterFallBackTest.cs" />
     <Compile Include="Events\EventSerializationTests.cs" />
+    <Compile Include="Events\StatsEventTests.cs" />
     <Compile Include="Monitor\HealthStatusTests.cs" />
     <Compile Include="HttpServiceRequestTests.cs" />
     <Compile Include="IDemoService.cs" />

tests/Gigya.Microdot.UnitTests/ServiceProxyTests/BehaviorTests.cs

@@ -5,7 +5,6 @@
 using System.Runtime.Remoting.Messaging;
 using System.Threading.Tasks;
 using FluentAssertions;
-
 using Gigya.Common.Application.HttpService.Client;
 using Gigya.Common.Contracts.Exceptions;
 using Gigya.Microdot.Fakes;
@@ -15,6 +14,7 @@
 using Gigya.Microdot.ServiceProxy;
 using Gigya.Microdot.SharedLogic.Events;
 using Gigya.Microdot.SharedLogic.Exceptions;
+using Gigya.Microdot.SharedLogic.Measurement;
 using Gigya.Microdot.Testing;
 using Gigya.Microdot.Testing.Shared;
 using Newtonsoft.Json;
@@ -450,5 +450,22 @@ public async Task ToUpper_MethodCallFailsWithInvalidJson_CorrectExceptionIsThrow
             actual.EncryptedTags["responseContent"].ShouldBe(badJson);
             actual.InnerException.ShouldBeAssignableTo<JsonException>();
         }
+
+        [Test]
+        public async Task RequestTimings_ValidCall_ServicesCallsDictionaryContainsCall()
+        {
+            //To create it on current context
+            var timings = RequestTimings.Current;
+
+            var messageHandler = new MockHttpMessageHandler();
+            messageHandler.When("*").Respond(HttpResponseFactory.GetResponse(content: $"''"));
+
+            RequestTimings.Current.ServicesCallsDictionary.Count.ShouldBe(0);
+
+            await CreateClient(messageHandler).ToUpper("aaaa");            
+
+            RequestTimings.Current.ServicesCallsDictionary.Count.ShouldBe(1);
+            RequestTimings.Current.ServicesCallsDictionary.ShouldContainKey(SERVICE_NAME);            
+        }
     }
 }