diff --git a/Gigya.Microdot.Hosting/Events/StatsEvent.cs b/Gigya.Microdot.Hosting/Events/StatsEvent.cs index f98e71c1..287f48f6 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.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> 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; + } } } \ 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 diff --git a/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs b/tests/Gigya.Microdot.UnitTests/Events/StatsEventTests.cs new file mode 100644 index 00000000..a6ab45c2 --- /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.Should().BeApproximately(expected.Value, 0.0001); + } + } + + 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); + } } }