From b66d94efa3fd08b232916412d3f8caf4194e0ca7 Mon Sep 17 00:00:00 2001 From: Guy Rozenblat Date: Thu, 27 Sep 2018 18:05:11 +0300 Subject: [PATCH 1/3] Addition of stats.processing.time for logging --- Gigya.Microdot.Hosting/Events/StatsEvent.cs | 23 +++++++++++++++++-- .../ServiceProxyProvider.cs | 20 ++++++++++------ .../Gigya.Microdot.SharedLogic.csproj | 1 + .../Measurement/RequestTimings.cs | 6 ++--- .../Measurement/ServicesCallsDictionary.cs | 14 +++++++++++ SolutionVersion.cs | 6 ++--- 6 files changed, 55 insertions(+), 15 deletions(-) create mode 100644 Gigya.Microdot.SharedLogic/Measurement/ServicesCallsDictionary.cs diff --git a/Gigya.Microdot.Hosting/Events/StatsEvent.cs b/Gigya.Microdot.Hosting/Events/StatsEvent.cs index f98e71c1..9d55d6fb 100644 --- a/Gigya.Microdot.Hosting/Events/StatsEvent.cs +++ b/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,7 +44,9 @@ public IEnumerable> 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; @@ -51,9 +54,12 @@ public IEnumerable> UserStats } - [EventField(EventConsts.statsTotalTime, OmitFromAudit = true)] + [EventField("stats.total.time", OmitFromAudit = true)] public virtual double? TotalTime => Timings.Value.Request.ElapsedMS; + [EventField("stats.processing.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,20 @@ public IEnumerable> 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; + } + return TotalTime - servicesTime; + } } } \ No newline at end of file diff --git a/Gigya.Microdot.ServiceProxy/ServiceProxyProvider.cs b/Gigya.Microdot.ServiceProxy/ServiceProxyProvider.cs index 2deb9fd2..ef46c16f 100644 --- a/Gigya.Microdot.ServiceProxy/ServiceProxyProvider.cs +++ b/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 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 values)) { var time = values.FirstOrDefault(); diff --git a/Gigya.Microdot.SharedLogic/Gigya.Microdot.SharedLogic.csproj b/Gigya.Microdot.SharedLogic/Gigya.Microdot.SharedLogic.csproj index 2aadab6c..fe7787b8 100644 --- a/Gigya.Microdot.SharedLogic/Gigya.Microdot.SharedLogic.csproj +++ b/Gigya.Microdot.SharedLogic/Gigya.Microdot.SharedLogic.csproj @@ -53,6 +53,7 @@ + diff --git a/Gigya.Microdot.SharedLogic/Measurement/RequestTimings.cs b/Gigya.Microdot.SharedLogic/Measurement/RequestTimings.cs index 1fe1e4be..7c159188 100644 --- a/Gigya.Microdot.SharedLogic/Measurement/RequestTimings.cs +++ b/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. [Serializable] - public class RequestTimings:MarshalByRefObject + public class RequestTimings : MarshalByRefObject { internal readonly ConcurrentDictionary UserStats = new ConcurrentDictionary(); + public ServicesCallsDictionary ServicesCallsDictionary = new ServicesCallsDictionary(); + /// Time of the ongoing request. public ConcurrentStopwatch Request = new ConcurrentStopwatch(); @@ -67,7 +69,5 @@ public static void ClearCurrentTimings() /// Starts measuring the top-level processing of the current request. Handy when it's inconvenient for you /// to call Request.Measure() public void MarkRequestStartTime() { Request.Start(); } - - } } diff --git a/Gigya.Microdot.SharedLogic/Measurement/ServicesCallsDictionary.cs b/Gigya.Microdot.SharedLogic/Measurement/ServicesCallsDictionary.cs new file mode 100644 index 00000000..a9fd47ac --- /dev/null +++ b/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 + { + public new ConcurrentStopwatch this[string serviceName] { get { return GetOrAdd(serviceName, x => new ConcurrentStopwatch()); } } + } +} diff --git a/SolutionVersion.cs b/SolutionVersion.cs index a3694190..609fbb38 100644 --- a/SolutionVersion.cs +++ b/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 From e263a4eaf4da144fd4aac5588a47b4cb0d5e71f1 Mon Sep 17 00:00:00 2001 From: Guy Rozenblat Date: Wed, 10 Oct 2018 18:22:23 +0300 Subject: [PATCH 2/3] Tests + Fixes --- Gigya.Microdot.Hosting/Events/StatsEvent.cs | 5 +- .../Events/StatsEventTests.cs | 52 +++++++++++++++++++ .../Gigya.Microdot.UnitTests.csproj | 1 + .../ServiceProxyTests/BehaviorTests.cs | 19 ++++++- 4 files changed, 75 insertions(+), 2 deletions(-) create mode 100644 tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs diff --git a/Gigya.Microdot.Hosting/Events/StatsEvent.cs b/Gigya.Microdot.Hosting/Events/StatsEvent.cs index 9d55d6fb..287f48f6 100644 --- a/Gigya.Microdot.Hosting/Events/StatsEvent.cs +++ b/Gigya.Microdot.Hosting/Events/StatsEvent.cs @@ -57,7 +57,7 @@ public IEnumerable> UserStats [EventField("stats.total.time", OmitFromAudit = true)] public virtual double? TotalTime => Timings.Value.Request.ElapsedMS; - [EventField("stats.processing.time", OmitFromAudit = true)] + [EventField("stats.netprocessing.time", OmitFromAudit = true)] public double? ProcessingTime => CalculateProcessingTime(); [EventField("stats.mysql.time", OmitFromAudit = true)] @@ -173,6 +173,9 @@ public IEnumerable> UserStats servicesTime += serviceCall.ElapsedMS.Value; } + if (servicesTime == 0) + return null; + return TotalTime - servicesTime; } diff --git a/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs b/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs new file mode 100644 index 00000000..d18f6a82 --- /dev/null +++ b/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.ShouldBe(expected); + } + } + + internal class MockStatsEvent : StatsEvent + { + + } +} diff --git a/tests/Gigya.Microdot.UnitTests/Gigya.Microdot.UnitTests.csproj b/tests/Gigya.Microdot.UnitTests/Gigya.Microdot.UnitTests.csproj index 791efb2e..e0853459 100644 --- a/tests/Gigya.Microdot.UnitTests/Gigya.Microdot.UnitTests.csproj +++ b/tests/Gigya.Microdot.UnitTests/Gigya.Microdot.UnitTests.csproj @@ -63,6 +63,7 @@ + diff --git a/tests/Gigya.Microdot.UnitTests/ServiceProxyTests/BehaviorTests.cs b/tests/Gigya.Microdot.UnitTests/ServiceProxyTests/BehaviorTests.cs index 5da648c0..ecad01f8 100644 --- a/tests/Gigya.Microdot.UnitTests/ServiceProxyTests/BehaviorTests.cs +++ b/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(); } + + [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); + } } } From b83d4b51bd91787044e314237255b598cae6683e Mon Sep 17 00:00:00 2001 From: Guy Rozenblat Date: Wed, 10 Oct 2018 18:50:02 +0300 Subject: [PATCH 3/3] Fixed failing test --- tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs b/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs index d18f6a82..a6ab45c2 100644 --- a/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs +++ b/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs @@ -41,7 +41,7 @@ public async Task ProcessingTime_TotalTimeAndServicesTimeHaveValues_TotalTimeMin var expected = RequestTimings.Current.Request.ElapsedMS - RequestTimings.Current.ServicesCallsDictionary["Service1"].ElapsedMS - RequestTimings.Current.ServicesCallsDictionary["Service2"].ElapsedMS; - statsEvent.ProcessingTime.ShouldBe(expected); + statsEvent.ProcessingTime.Should().BeApproximately(expected.Value, 0.0001); } }