diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs index 8386fe65c6..7fc0929614 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs @@ -7,16 +7,26 @@ namespace Microsoft.Azure.Cosmos.Tracing.TraceData using System; using System.Collections.Generic; using System.Diagnostics; - using System.Net; using System.Net.Http; using System.Text; using Microsoft.Azure.Documents; - using Microsoft.Azure.Documents.Collections; internal sealed class ClientSideRequestStatisticsTraceDatum : TraceDatum, IClientSideRequestStatistics { - private readonly object lockObject = new object(); + private static readonly IReadOnlyDictionary EmptyEndpointToAddressResolutionStatistics = new Dictionary(); + private static readonly IReadOnlyList EmptyStoreResponseStatistics = new List(); + private static readonly IReadOnlyList EmptyHttpResponseStatistics = new List(); + + private readonly object requestEndTimeLock = new object(); private readonly long clientSideRequestStatisticsCreateTime; + private readonly Dictionary endpointToAddressResolutionStats; + private readonly Dictionary recordRequestHashCodeToStartTime; + private readonly List storeResponseStatistics; + private readonly List httpResponseStatistics; + + private IReadOnlyDictionary shallowCopyOfEndpointToAddressResolutionStatistics = null; + private IReadOnlyList shallowCopyOfStoreResponseStatistics = null; + private IReadOnlyList shallowCopyOfHttpResponseStatistics = null; private long? firstStartRequestTimestamp; private long? lastStartRequestTimestamp; @@ -27,36 +37,79 @@ public ClientSideRequestStatisticsTraceDatum(DateTime startTime) { this.RequestStartTimeUtc = startTime; this.RequestEndTimeUtc = null; - this.EndpointToAddressResolutionStatistics = new Dictionary(); - this.RecordRequestHashCodeToStartTime = new Dictionary(); + this.endpointToAddressResolutionStats = new Dictionary(); + this.recordRequestHashCodeToStartTime = new Dictionary(); this.ContactedReplicas = new List(); - this.StoreResponseStatisticsList = new List(); + this.storeResponseStatistics = new List(); this.FailedReplicas = new HashSet(); this.RegionsContactedWithName = new HashSet<(string, Uri)>(); this.clientSideRequestStatisticsCreateTime = Stopwatch.GetTimestamp(); - this.HttpResponseStatisticsList = new List(); + this.httpResponseStatistics = new List(); } public DateTime RequestStartTimeUtc { get; } - public DateTime? RequestEndTimeUtc { get; set; } + public DateTime? RequestEndTimeUtc { get; private set; } - public Dictionary EndpointToAddressResolutionStatistics { get; } + public IReadOnlyDictionary EndpointToAddressResolutionStatistics + { + get + { + if (this.endpointToAddressResolutionStats.Count == 0) + { + return ClientSideRequestStatisticsTraceDatum.EmptyEndpointToAddressResolutionStatistics; + } - private Dictionary RecordRequestHashCodeToStartTime { get; } + lock (this.endpointToAddressResolutionStats) + { + this.shallowCopyOfEndpointToAddressResolutionStatistics ??= new Dictionary(this.endpointToAddressResolutionStats); + return this.shallowCopyOfEndpointToAddressResolutionStatistics; + } + } + } public List ContactedReplicas { get; set; } - public List StoreResponseStatisticsList { get; } - - public List HttpResponseStatisticsList { get; } - public HashSet FailedReplicas { get; } public HashSet RegionsContacted { get; } public HashSet<(string, Uri)> RegionsContactedWithName { get; } + public IReadOnlyList StoreResponseStatisticsList + { + get + { + if (this.storeResponseStatistics.Count == 0) + { + return ClientSideRequestStatisticsTraceDatum.EmptyStoreResponseStatistics; + } + + lock (this.storeResponseStatistics) + { + this.shallowCopyOfStoreResponseStatistics ??= new List(this.storeResponseStatistics); + return this.shallowCopyOfStoreResponseStatistics; + } + } + } + + public IReadOnlyList HttpResponseStatisticsList + { + get + { + if (this.httpResponseStatistics.Count == 0) + { + return ClientSideRequestStatisticsTraceDatum.EmptyHttpResponseStatistics; + } + + lock (this.httpResponseStatistics) + { + this.shallowCopyOfHttpResponseStatistics ??= new List(this.httpResponseStatistics); + return this.shallowCopyOfHttpResponseStatistics; + } + } + } + public TimeSpan RequestLatency { get @@ -91,7 +144,7 @@ public TimeSpan EstimatedClientDelayFromAllCauses public void RecordRequest(DocumentServiceRequest request) { - lock (this.lockObject) + lock (this.recordRequestHashCodeToStartTime) { long timestamp = Stopwatch.GetTimestamp(); if (this.received429ResponseSinceLastStartRequest) @@ -107,25 +160,28 @@ public void RecordRequest(DocumentServiceRequest request) this.lastStartRequestTimestamp = timestamp; this.received429ResponseSinceLastStartRequest = false; - } - this.RecordRequestHashCodeToStartTime[request.GetHashCode()] = DateTime.UtcNow; + this.recordRequestHashCodeToStartTime[request.GetHashCode()] = DateTime.UtcNow; + } } public void RecordResponse(DocumentServiceRequest request, StoreResult storeResult) { // One DocumentServiceRequest can map to multiple store results DateTime? startDateTime = null; - if (this.RecordRequestHashCodeToStartTime.TryGetValue(request.GetHashCode(), out DateTime startRequestTime)) + lock (this.recordRequestHashCodeToStartTime) { - startDateTime = startRequestTime; - } - else - { - Debug.Fail("DocumentServiceRequest start time not recorded"); + if (this.recordRequestHashCodeToStartTime.TryGetValue(request.GetHashCode(), out DateTime startRequestTime)) + { + startDateTime = startRequestTime; + } + else + { + Debug.Fail("DocumentServiceRequest start time not recorded"); + } } - DateTime responseTime = DateTime.UtcNow; + DateTime responseTime = this.GetAndUpdateRequestEndTime(); Uri locationEndpoint = request.RequestContext.LocationEndpointToRoute; string regionName = request.RequestContext.RegionName; StoreResponseStatistics responseStatistics = new StoreResponseStatistics( @@ -141,19 +197,16 @@ public void RecordResponse(DocumentServiceRequest request, StoreResult storeResu this.IsCpuOverloaded = true; } - lock (this.lockObject) + lock (this.storeResponseStatistics) { - if (!this.RequestEndTimeUtc.HasValue || responseTime > this.RequestEndTimeUtc) - { - this.RequestEndTimeUtc = responseTime; - } - if (locationEndpoint != null) { this.RegionsContactedWithName.Add((regionName, locationEndpoint)); } - this.StoreResponseStatisticsList.Add(responseStatistics); + // Reset the shallow copy + this.shallowCopyOfStoreResponseStatistics = null; + this.storeResponseStatistics.Add(responseStatistics); if (!this.received429ResponseSinceLastStartRequest && storeResult.StatusCode == StatusCodes.TooManyRequests) @@ -171,9 +224,11 @@ public string RecordAddressResolutionStart(Uri targetEndpoint) endTime: DateTime.MaxValue, targetEndpoint: targetEndpoint == null ? "" : targetEndpoint.ToString()); - lock (this.lockObject) + lock (this.endpointToAddressResolutionStats) { - this.EndpointToAddressResolutionStatistics.Add(identifier, resolutionStats); + // Reset the shallow copy + this.shallowCopyOfEndpointToAddressResolutionStatistics = null; + this.endpointToAddressResolutionStats.Add(identifier, resolutionStats); } return identifier; @@ -186,37 +241,36 @@ public void RecordAddressResolutionEnd(string identifier) return; } - DateTime responseTime = DateTime.UtcNow; - lock (this.lockObject) + DateTime responseTime = this.GetAndUpdateRequestEndTime(); + + lock (this.endpointToAddressResolutionStats) { - if (!this.EndpointToAddressResolutionStatistics.ContainsKey(identifier)) + if (!this.endpointToAddressResolutionStats.ContainsKey(identifier)) { throw new ArgumentException("Identifier {0} does not exist. Please call start before calling end.", identifier); } - if (!this.RequestEndTimeUtc.HasValue || responseTime > this.RequestEndTimeUtc) - { - this.RequestEndTimeUtc = responseTime; - } - - AddressResolutionStatistics start = this.EndpointToAddressResolutionStatistics[identifier]; + AddressResolutionStatistics start = this.endpointToAddressResolutionStats[identifier]; - this.EndpointToAddressResolutionStatistics[identifier] = new AddressResolutionStatistics( + // Reset the shallow copy + this.shallowCopyOfEndpointToAddressResolutionStatistics = null; + this.endpointToAddressResolutionStats[identifier] = new AddressResolutionStatistics( start.StartTime, responseTime, start.TargetEndpoint); } } - public void RecordHttpResponse(HttpRequestMessage request, - HttpResponseMessage response, + public void RecordHttpResponse(HttpRequestMessage request, + HttpResponseMessage response, ResourceType resourceType, DateTime requestStartTimeUtc) { - lock (this.lockObject) + lock (this.httpResponseStatistics) { - DateTime requestEndTimeUtc = this.RecordHttpResponseEndTime(); - this.HttpResponseStatisticsList.Add(new HttpResponseStatistics(requestStartTimeUtc, + this.shallowCopyOfHttpResponseStatistics = null; + DateTime requestEndTimeUtc = this.GetAndUpdateRequestEndTime(); + this.httpResponseStatistics.Add(new HttpResponseStatistics(requestStartTimeUtc, requestEndTimeUtc, request.RequestUri, request.Method, @@ -231,10 +285,11 @@ public void RecordHttpException(HttpRequestMessage request, ResourceType resourceType, DateTime requestStartTimeUtc) { - lock (this.lockObject) + lock (this.httpResponseStatistics) { - DateTime requestEndTimeUtc = this.RecordHttpResponseEndTime(); - this.HttpResponseStatisticsList.Add(new HttpResponseStatistics(requestStartTimeUtc, + this.shallowCopyOfHttpResponseStatistics = null; + DateTime requestEndTimeUtc = this.GetAndUpdateRequestEndTime(); + this.httpResponseStatistics.Add(new HttpResponseStatistics(requestStartTimeUtc, requestEndTimeUtc, request.RequestUri, request.Method, @@ -244,12 +299,15 @@ public void RecordHttpException(HttpRequestMessage request, } } - private DateTime RecordHttpResponseEndTime() + private DateTime GetAndUpdateRequestEndTime() { DateTime requestEndTimeUtc = DateTime.UtcNow; - if (!this.RequestEndTimeUtc.HasValue || requestEndTimeUtc > this.RequestEndTimeUtc) + lock (this.requestEndTimeLock) { - this.RequestEndTimeUtc = requestEndTimeUtc; + if (!this.RequestEndTimeUtc.HasValue || requestEndTimeUtc > this.RequestEndTimeUtc) + { + this.RequestEndTimeUtc = requestEndTimeUtc; + } } return requestEndTimeUtc; diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs index a19680692d..345c0d382b 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs @@ -213,9 +213,9 @@ public void Visit(ClientSideRequestStatisticsTraceDatum clientSideRequestStatist this.jsonWriter.WriteFieldName("AddressResolutionStatistics"); this.jsonWriter.WriteArrayStart(); - foreach (ClientSideRequestStatisticsTraceDatum.AddressResolutionStatistics stat in clientSideRequestStatisticsTraceDatum.EndpointToAddressResolutionStatistics.Values) + foreach (KeyValuePair stat in clientSideRequestStatisticsTraceDatum.EndpointToAddressResolutionStatistics) { - this.VisitAddressResolutionStatistics(stat); + this.VisitAddressResolutionStatistics(stat.Value); } this.jsonWriter.WriteArrayEnd(); diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceTextWriter.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceTextWriter.cs index 14f95365b2..575acabce3 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceTextWriter.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceTextWriter.cs @@ -382,12 +382,12 @@ public void Visit(ClientSideRequestStatisticsTraceDatum clientSideRequestStatist stringBuilder.AppendLine(AddressResolutionStatisticsTextTable.Singleton.TopLine); stringBuilder.AppendLine(AddressResolutionStatisticsTextTable.Singleton.Header); stringBuilder.AppendLine(AddressResolutionStatisticsTextTable.Singleton.MiddleLine); - foreach (AddressResolutionStatistics stat in clientSideRequestStatisticsTraceDatum.EndpointToAddressResolutionStatistics.Values) + foreach (KeyValuePair stat in clientSideRequestStatisticsTraceDatum.EndpointToAddressResolutionStatistics) { string row = AddressResolutionStatisticsTextTable.Singleton.GetRow( - stat.StartTime.ToString("hh:mm:ss:fff", CultureInfo.InvariantCulture), - stat.EndTime.HasValue ? stat.EndTime.Value.ToString("hh:mm:ss:fff", CultureInfo.InvariantCulture) : "NO END TIME", - stat.TargetEndpoint); + stat.Value.StartTime.ToString("hh:mm:ss:fff", CultureInfo.InvariantCulture), + stat.Value.EndTime.HasValue ? stat.Value.EndTime.Value.ToString("hh:mm:ss:fff", CultureInfo.InvariantCulture) : "NO END TIME", + stat.Value.TargetEndpoint); stringBuilder.AppendLine(row); } @@ -440,7 +440,7 @@ public void Visit(ClientSideRequestStatisticsTraceDatum clientSideRequestStatist } } - if (clientSideRequestStatisticsTraceDatum.HttpResponseStatisticsList.Count > 0) + if (clientSideRequestStatisticsTraceDatum.HttpResponseStatisticsList.Any()) { stringBuilder.AppendLine("Http Response Statistics"); foreach (HttpResponseStatistics stat in clientSideRequestStatisticsTraceDatum.HttpResponseStatisticsList) diff --git a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/BaselineTest/TestBaseline/TraceWriterBaselineTests.TraceData.xml b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/BaselineTest/TestBaseline/TraceWriterBaselineTests.TraceData.xml index aa3d5c7f27..8fb479a006 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/BaselineTest/TestBaseline/TraceWriterBaselineTests.TraceData.xml +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/BaselineTest/TestBaseline/TraceWriterBaselineTests.TraceData.xml @@ -214,8 +214,9 @@ DateTime.MinValue, DateTime.MaxValue, "http://localhost.com"); - datum.EndpointToAddressResolutionStatistics["asdf"] = mockStatistics; - datum.EndpointToAddressResolutionStatistics["asdf2"] = mockStatistics; + + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf", mockStatistics); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf2", mockStatistics); datum.FailedReplicas.Add(uri1); datum.FailedReplicas.Add(uri2); @@ -223,7 +224,7 @@ datum.RegionsContactedWithName.Add(("local", uri1)); datum.RegionsContactedWithName.Add(("local", uri2)); - datum.RequestEndTimeUtc = DateTime.MaxValue; + TraceWriterBaselineTests.SetEndRequestTime(datum, DateTime.MaxValue); StoreResponseStatistics storeResponseStatistics = new StoreResponseStatistics( DateTime.MinValue, @@ -250,7 +251,8 @@ ResourceType.Document, OperationType.Query, uri1); - datum.StoreResponseStatisticsList.Add(storeResponseStatistics); + + TraceWriterBaselineTests.GetPrivateField>(datum, "storeResponseStatistics").Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats", datum); } ]]> @@ -417,18 +419,14 @@ ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue); datum.ContactedReplicas.Add(default); - ClientSideRequestStatisticsTraceDatum.AddressResolutionStatistics mockStatistics = new ClientSideRequestStatisticsTraceDatum.AddressResolutionStatistics( - default, - default, - targetEndpoint: "asdf"); - datum.EndpointToAddressResolutionStatistics["asdf"] = default; - datum.EndpointToAddressResolutionStatistics["asdf2"] = default; + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf", default); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf2", default); datum.FailedReplicas.Add(default); datum.RegionsContactedWithName.Add(default); - datum.RequestEndTimeUtc = default; + TraceWriterBaselineTests.SetEndRequestTime(datum, default); StoreResponseStatistics storeResponseStatistics = new StoreResponseStatistics( requestStartTime: default, @@ -451,11 +449,12 @@ usingLocalLSN: default, activityId: default, backendRequestDurationInMs: default, - transportRequestStats: TraceWriterBaselineTests.CreateTransportRequestStats()), + transportRequestStats: TraceWriterBaselineTests.CreateTransportRequestStats()), resourceType: default, operationType: default, - locationEndpoint: default); ; - datum.StoreResponseStatisticsList.Add(storeResponseStatistics); + locationEndpoint: default); + + TraceWriterBaselineTests.GetPrivateField>(datum, "storeResponseStatistics").Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats Default", datum); } ]]> @@ -607,10 +606,8 @@ TraceForBaselineTesting rootTrace; using (rootTrace = TraceForBaselineTesting.GetRootTrace()) { - ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue) - { - RequestEndTimeUtc = DateTime.MaxValue - }; + ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue); + TraceWriterBaselineTests.SetEndRequestTime(datum,DateTime.MaxValue); HttpResponseStatistics httpResponseStatistics = new HttpResponseStatistics( DateTime.MinValue, @@ -619,9 +616,9 @@ HttpMethod.Get, ResourceType.Document, new HttpResponseMessage(System.Net.HttpStatusCode.OK) { ReasonPhrase = "Success" }, - exception: null - ); - datum.HttpResponseStatisticsList.Add(httpResponseStatistics); + exception: null); + + TraceWriterBaselineTests.GetPrivateField>(datum, "httpResponseStatistics").Add(httpResponseStatistics); HttpResponseStatistics httpResponseStatisticsException = new HttpResponseStatistics( DateTime.MinValue, @@ -630,9 +627,8 @@ HttpMethod.Get, ResourceType.Document, responseMessage: null, - exception: new OperationCanceledException() - ); - datum.HttpResponseStatisticsList.Add(httpResponseStatisticsException); + exception: new OperationCanceledException()); + TraceWriterBaselineTests.GetPrivateField>(datum, "httpResponseStatistics").Add(httpResponseStatisticsException); rootTrace.AddDatum("Client Side Request Stats", datum); } diff --git a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerTests.cs index a0c2f408e8..a075d439f6 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerTests.cs @@ -20,6 +20,7 @@ namespace Microsoft.Azure.Cosmos.Tests public class GlobalPartitionEndpointManagerTests { [TestMethod] + [Timeout(10000)] public async Task TestWriteForbiddenScenarioAsync() { GlobalPartitionEndpointManagerTests.SetupAccountAndCacheOperations( @@ -72,9 +73,6 @@ public async Task TestWriteForbiddenScenarioAsync() Convert.ToBase64String(Encoding.UTF8.GetBytes(Guid.NewGuid().ToString())), cosmosClientOptions)) { - - - Container container = customClient.GetContainer(databaseName, containerName); ToDoActivity toDoActivity = new ToDoActivity() @@ -106,12 +104,10 @@ public async Task TestWriteForbiddenScenarioAsync() response = await container.CreateItemAsync(toDoActivity2, new Cosmos.PartitionKey(toDoActivity2.Pk)); Assert.AreEqual(HttpStatusCode.Created, response.StatusCode); } - - await Task.Delay(TimeSpan.FromMinutes(5)); - Console.WriteLine("done"); } [TestMethod] + [Timeout(10000)] public async Task TestServiceUnavailableExceptionScenarioAsync() { GlobalPartitionEndpointManagerTests.SetupAccountAndCacheOperations( @@ -208,6 +204,7 @@ public async Task TestServiceUnavailableExceptionScenarioAsync() } [TestMethod] + [Timeout(10000)] public async Task TestRequestTimeoutExceptionScenarioAsync() { GlobalPartitionEndpointManagerTests.SetupAccountAndCacheOperations( diff --git a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerUnitTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerUnitTests.cs index a12158861a..8f1da91c53 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerUnitTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/PartitionKeyRangeFailoverTests/GlobalPartitionEndpointManagerUnitTests.cs @@ -21,6 +21,7 @@ namespace Microsoft.Azure.Cosmos.Tests public class GlobalPartitionEndpointManagerUnitTests { [TestMethod] + [Timeout(10000)] public void TestSingleReadRegionScenario() { Mock mockEndpointManager = new Mock(MockBehavior.Strict); @@ -66,6 +67,7 @@ public void TestSingleReadRegionScenario() [DataRow(5)] [DataRow(10)] [DataRow(100)] + [Timeout(30000)] public void VerifyAllReadRegionsAreVisited(int numOfReadRegions) { Mock mockEndpointManager = new Mock(MockBehavior.Strict); diff --git a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs new file mode 100644 index 0000000000..fa5534d5ba --- /dev/null +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs @@ -0,0 +1,164 @@ +namespace Microsoft.Azure.Cosmos.Tests.Tracing +{ + using System; + using System.Collections.Generic; + using System.Linq; + using System.Net.Http; + using System.Threading; + using System.Threading.Tasks; + using Microsoft.Azure.Cosmos.Diagnostics; + using Microsoft.Azure.Cosmos.Tracing.TraceData; + using Microsoft.Azure.Documents; + using Microsoft.VisualStudio.TestTools.UnitTesting; + + [TestClass] + public class ClientSideRequestStatisticsTraceDatumTests + { + private static readonly HttpResponseMessage response = new HttpResponseMessage(); + private static readonly HttpRequestMessage request = new HttpRequestMessage(); + private static readonly Uri uri = new Uri("http://someUri1.com"); + private static readonly DocumentServiceRequest requestDsr = DocumentServiceRequest.Create(OperationType.Read, resourceType: ResourceType.Document, authorizationTokenType: AuthorizationTokenType.PrimaryMasterKey); + private static readonly StoreResult storeResult = new Documents.StoreResult( + storeResponse: new StoreResponse(), + exception: null, + partitionKeyRangeId: 42.ToString(), + lsn: 1337, + quorumAckedLsn: 23, + requestCharge: 3.14, + currentReplicaSetSize: 4, + currentWriteQuorum: 3, + isValid: true, + storePhysicalAddress: new Uri("http://storephysicaladdress.com"), + globalCommittedLSN: 1234, + numberOfReadRegions: 13, + itemLSN: 15, + sessionToken: new SimpleSessionToken(42), + usingLocalLSN: true, + activityId: Guid.Empty.ToString(), + backendRequestDurationInMs: "4.2", + transportRequestStats: TraceWriterBaselineTests.CreateTransportRequestStats()); + + /// + /// This test is needed because different parts of the SDK use the same ClientSideRequestStatisticsTraceDatum across multiple + /// threads. It's even possible that there are background threads referencing the same instance. + /// + [TestMethod] + [Timeout(5000)] + public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() + { + await this.ConcurrentUpdateTestHelper>( + (clientSideRequestStatistics, cancellationToken) => this.UpdateAddressesInBackground(clientSideRequestStatistics, cancellationToken), + (clientSideRequestStatistics) => clientSideRequestStatistics.EndpointToAddressResolutionStatistics); + } + + [TestMethod] + [Timeout(5000)] + public async Task ConcurrentUpdateHttpResponseStatisticsListTests() + { + await this.ConcurrentUpdateTestHelper( + (clientSideRequestStatistics, cancellationToken) => this.UpdateHttpResponsesInBackground(clientSideRequestStatistics, cancellationToken), + (clientSideRequestStatistics) => clientSideRequestStatistics.HttpResponseStatisticsList); + } + + [TestMethod] + [Timeout(5000)] + public async Task ConcurrentUpdateStoreResponseStatisticsListTests() + { + await this.ConcurrentUpdateTestHelper( + (clientSideRequestStatistics, cancellationToken) => this.UpdateStoreResponseStatisticsListInBackground(clientSideRequestStatistics, cancellationToken), + (clientSideRequestStatistics) => clientSideRequestStatistics.StoreResponseStatisticsList); + } + + private async Task ConcurrentUpdateTestHelper( + Action backgroundUpdater, + Func> getList) + { + using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); + + ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow); + + Task backgroundTask = Task.Run(() => backgroundUpdater(datum, cancellationTokenSource.Token)); + + // Wait for the background thread to start + for (int i = 0; i < 100; i++) + { + if (getList(datum).Any()) + { + break; + } + + if (backgroundTask.Exception != null || backgroundTask.IsCompleted || backgroundTask.IsFaulted || backgroundTask.IsCanceled) + { + Assert.Fail($"BackgroundTask stopped running. {backgroundTask.Exception}"); + } + + await Task.Delay(TimeSpan.FromMilliseconds(50)); + } + + Assert.IsTrue(getList(datum).Any(), $"BackgroundTask never started running."); + + foreach (T item in getList(datum)) + { + Assert.IsNotNull(item); + } + + int count = getList(datum).Count(); + using (IEnumerator enumerator = getList(datum).GetEnumerator()) + { + // Wait for the background thread to start + for (int i = 0; i < 100; i++) + { + // IEnumerator should not block items being added to the list + if (getList(datum).Count() != count) + { + break; + } + + await Task.Delay(TimeSpan.FromMilliseconds(50)); + } + + Assert.IsTrue(getList(datum).Count() > count, "Background task never updated the list."); + } + + cancellationTokenSource.Cancel(); + } + + private void UpdateAddressesInBackground( + ClientSideRequestStatisticsTraceDatum datum, + CancellationToken cancellationToken) + { + while (!cancellationToken.IsCancellationRequested) + { + string key = datum.RecordAddressResolutionStart(ClientSideRequestStatisticsTraceDatumTests.uri); + datum.RecordAddressResolutionEnd(key); + } + } + + private void UpdateHttpResponsesInBackground( + ClientSideRequestStatisticsTraceDatum datum, + CancellationToken cancellationToken) + { + while (!cancellationToken.IsCancellationRequested) + { + datum.RecordHttpResponse( + ClientSideRequestStatisticsTraceDatumTests.request, + ClientSideRequestStatisticsTraceDatumTests.response, + Documents.ResourceType.Document, + DateTime.UtcNow - TimeSpan.FromSeconds(5)); + } + } + + private void UpdateStoreResponseStatisticsListInBackground( + ClientSideRequestStatisticsTraceDatum datum, + CancellationToken cancellationToken) + { + while (!cancellationToken.IsCancellationRequested) + { + datum.RecordRequest(ClientSideRequestStatisticsTraceDatumTests.requestDsr); + datum.RecordResponse( + ClientSideRequestStatisticsTraceDatumTests.requestDsr, + ClientSideRequestStatisticsTraceDatumTests.storeResult); + } + } + } +} diff --git a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceTests.cs index 8e3de3caab..ad9fcd391c 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceTests.cs @@ -91,6 +91,7 @@ public void TestNoOpTrace() } [TestMethod] + [Timeout(5000)] public void ValidateStoreResultSerialization() { HashSet storeResultProperties = typeof(StoreResult).GetProperties(BindingFlags.Public | BindingFlags.Instance).Select(x => x.Name).ToHashSet(); @@ -127,7 +128,7 @@ public void ValidateStoreResultSerialization() OperationType.Query, new Uri("http://someUri1.com")); - datum.StoreResponseStatisticsList.Add(storeResponseStatistics); + ((List)datum.GetType().GetField("storeResponseStatistics", BindingFlags.NonPublic | BindingFlags.Instance).GetValue(datum)).Add(storeResponseStatistics); CosmosTraceDiagnostics diagnostics = new CosmosTraceDiagnostics(trace); string json = diagnostics.ToString(); diff --git a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceWriterBaselineTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceWriterBaselineTests.cs index 12b82b4bc2..86ba076226 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceWriterBaselineTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceWriterBaselineTests.cs @@ -80,6 +80,7 @@ public sealed class TraceWriterBaselineTests : BaselineTests inputs = new List(); @@ -267,6 +268,7 @@ public void Serialization() } [TestMethod] + [Timeout(5000)] public void TraceData() { List inputs = new List(); @@ -370,8 +372,9 @@ public void TraceData() DateTime.MinValue, DateTime.MaxValue, "http://localhost.com"); - datum.EndpointToAddressResolutionStatistics["asdf"] = mockStatistics; - datum.EndpointToAddressResolutionStatistics["asdf2"] = mockStatistics; + + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf", mockStatistics); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf2", mockStatistics); datum.FailedReplicas.Add(uri1); datum.FailedReplicas.Add(uri2); @@ -379,7 +382,7 @@ public void TraceData() datum.RegionsContactedWithName.Add(("local", uri1)); datum.RegionsContactedWithName.Add(("local", uri2)); - datum.RequestEndTimeUtc = DateTime.MaxValue; + TraceWriterBaselineTests.SetEndRequestTime(datum, DateTime.MaxValue); StoreResponseStatistics storeResponseStatistics = new StoreResponseStatistics( DateTime.MinValue, @@ -406,7 +409,8 @@ public void TraceData() ResourceType.Document, OperationType.Query, uri1); - datum.StoreResponseStatisticsList.Add(storeResponseStatistics); + + TraceWriterBaselineTests.GetPrivateField>(datum, "storeResponseStatistics").Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats", datum); } endLineNumber = GetLineNumber(); @@ -422,18 +426,14 @@ public void TraceData() ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue); datum.ContactedReplicas.Add(default); - ClientSideRequestStatisticsTraceDatum.AddressResolutionStatistics mockStatistics = new ClientSideRequestStatisticsTraceDatum.AddressResolutionStatistics( - default, - default, - targetEndpoint: "asdf"); - datum.EndpointToAddressResolutionStatistics["asdf"] = default; - datum.EndpointToAddressResolutionStatistics["asdf2"] = default; + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf", default); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf2", default); datum.FailedReplicas.Add(default); datum.RegionsContactedWithName.Add(default); - datum.RequestEndTimeUtc = default; + TraceWriterBaselineTests.SetEndRequestTime(datum, default); StoreResponseStatistics storeResponseStatistics = new StoreResponseStatistics( requestStartTime: default, @@ -456,11 +456,12 @@ public void TraceData() usingLocalLSN: default, activityId: default, backendRequestDurationInMs: default, - transportRequestStats: TraceWriterBaselineTests.CreateTransportRequestStats()), + transportRequestStats: TraceWriterBaselineTests.CreateTransportRequestStats()), resourceType: default, operationType: default, - locationEndpoint: default); ; - datum.StoreResponseStatisticsList.Add(storeResponseStatistics); + locationEndpoint: default); + + TraceWriterBaselineTests.GetPrivateField>(datum, "storeResponseStatistics").Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats Default", datum); } endLineNumber = GetLineNumber(); @@ -473,10 +474,8 @@ public void TraceData() TraceForBaselineTesting rootTrace; using (rootTrace = TraceForBaselineTesting.GetRootTrace()) { - ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue) - { - RequestEndTimeUtc = DateTime.MaxValue - }; + ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue); + TraceWriterBaselineTests.SetEndRequestTime(datum,DateTime.MaxValue); HttpResponseStatistics httpResponseStatistics = new HttpResponseStatistics( DateTime.MinValue, @@ -485,9 +484,9 @@ public void TraceData() HttpMethod.Get, ResourceType.Document, new HttpResponseMessage(System.Net.HttpStatusCode.OK) { ReasonPhrase = "Success" }, - exception: null - ); - datum.HttpResponseStatisticsList.Add(httpResponseStatistics); + exception: null); + + TraceWriterBaselineTests.GetPrivateField>(datum, "httpResponseStatistics").Add(httpResponseStatistics); HttpResponseStatistics httpResponseStatisticsException = new HttpResponseStatistics( DateTime.MinValue, @@ -496,9 +495,8 @@ public void TraceData() HttpMethod.Get, ResourceType.Document, responseMessage: null, - exception: new OperationCanceledException() - ); - datum.HttpResponseStatisticsList.Add(httpResponseStatisticsException); + exception: new OperationCanceledException()); + TraceWriterBaselineTests.GetPrivateField>(datum, "httpResponseStatistics").Add(httpResponseStatisticsException); rootTrace.AddDatum("Client Side Request Stats", datum); } @@ -538,6 +536,7 @@ public void TraceData() } [TestMethod] + [Timeout(5000)] public async Task ScenariosAsync() { List inputs = new List(); @@ -755,6 +754,20 @@ internal static TransportRequestStats CreateTransportRequestStats() return transportRequestStats; } + internal static T GetPrivateField( + ClientSideRequestStatisticsTraceDatum datum, + string propertyName) + { + return (T)datum.GetType().GetField(propertyName, BindingFlags.NonPublic | BindingFlags.Instance).GetValue(datum); + } + + internal static void SetEndRequestTime( + ClientSideRequestStatisticsTraceDatum datum, + DateTime? dateTime) + { + datum.GetType().GetProperty("RequestEndTimeUtc").SetValue(datum, dateTime); + } + private static IQueryPipelineStage CreatePipeline(IDocumentContainer documentContainer, string query, int pageSize = 10, CosmosElement state = null) { TryCatch tryCreatePipeline = PipelineFactory.MonadicCreate( @@ -764,7 +777,7 @@ private static IQueryPipelineStage CreatePipeline(IDocumentContainer documentCon new List() { FeedRangeEpk.FullRange }, partitionKey: null, GetQueryPlan(query), - new QueryPaginationOptions(pageSizeHint: 10), + new QueryPaginationOptions(pageSizeHint: pageSize), maxConcurrency: 10, requestCancellationToken: default, requestContinuationToken: state);