From d9bfb1b197341467523369b605f3c1d6ed93546a Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Wed, 2 Jun 2021 10:34:00 -0700 Subject: [PATCH 01/10] Fix race condition --- .../ClientSideRequestStatisticsTraceDatum.cs | 84 +++++++--- .../Tracing/TraceWriter.TraceJsonWriter.cs | 6 +- .../Tracing/TraceWriter.TraceTextWriter.cs | 10 +- .../GatewayClientSideRequestStatsTests.cs | 26 ++- ...entSideRequestStatisticsTraceDatumTests.cs | 155 ++++++++++++++++++ .../Tracing/TraceTests.cs | 2 +- .../Tracing/TraceWriterBaselineTests.cs | 39 +++-- 7 files changed, 260 insertions(+), 62 deletions(-) create mode 100644 Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs index 8386fe65c6..66513afa9e 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs @@ -7,16 +7,18 @@ 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 readonly long clientSideRequestStatisticsCreateTime; + private readonly Dictionary endpointToAddressResolutionStats; + private readonly Dictionary recordRequestHashCodeToStartTime; + private readonly List storeResponseStatistics; + private readonly List httpResponseStatistics; private long? firstStartRequestTimestamp; private long? lastStartRequestTimestamp; @@ -27,36 +29,70 @@ 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 Dictionary EndpointToAddressResolutionStatistics { get; } - - private Dictionary RecordRequestHashCodeToStartTime { get; } + public IEnumerable> EndpointToAddressResolutionStatistics + { + get + { + lock (this.lockObject) + { + foreach (KeyValuePair a in this.endpointToAddressResolutionStats) + { + yield return a; + } + } + } + } 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 IEnumerable StoreResponseStatisticsList + { + get + { + lock (this.lockObject) + { + foreach (StoreResponseStatistics storeResponseStatistic in this.storeResponseStatistics) + { + yield return storeResponseStatistic; + } + } + } + } + + public IEnumerable HttpResponseStatisticsList + { + get + { + lock (this.httpResponseStatistics) + { + foreach (HttpResponseStatistics httpResponseStatistic in this.httpResponseStatistics) + { + yield return httpResponseStatistic; + } + } + } + } + public TimeSpan RequestLatency { get @@ -109,14 +145,14 @@ public void RecordRequest(DocumentServiceRequest request) 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)) + if (this.recordRequestHashCodeToStartTime.TryGetValue(request.GetHashCode(), out DateTime startRequestTime)) { startDateTime = startRequestTime; } @@ -153,7 +189,7 @@ public void RecordResponse(DocumentServiceRequest request, StoreResult storeResu this.RegionsContactedWithName.Add((regionName, locationEndpoint)); } - this.StoreResponseStatisticsList.Add(responseStatistics); + this.storeResponseStatistics.Add(responseStatistics); if (!this.received429ResponseSinceLastStartRequest && storeResult.StatusCode == StatusCodes.TooManyRequests) @@ -173,7 +209,7 @@ public string RecordAddressResolutionStart(Uri targetEndpoint) lock (this.lockObject) { - this.EndpointToAddressResolutionStatistics.Add(identifier, resolutionStats); + this.endpointToAddressResolutionStats.Add(identifier, resolutionStats); } return identifier; @@ -189,7 +225,7 @@ public void RecordAddressResolutionEnd(string identifier) DateTime responseTime = DateTime.UtcNow; lock (this.lockObject) { - 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); } @@ -199,9 +235,9 @@ public void RecordAddressResolutionEnd(string identifier) this.RequestEndTimeUtc = responseTime; } - AddressResolutionStatistics start = this.EndpointToAddressResolutionStatistics[identifier]; + AddressResolutionStatistics start = this.endpointToAddressResolutionStats[identifier]; - this.EndpointToAddressResolutionStatistics[identifier] = new AddressResolutionStatistics( + this.endpointToAddressResolutionStats[identifier] = new AddressResolutionStatistics( start.StartTime, responseTime, start.TargetEndpoint); @@ -213,10 +249,10 @@ public void RecordHttpResponse(HttpRequestMessage request, ResourceType resourceType, DateTime requestStartTimeUtc) { - lock (this.lockObject) + lock (this.httpResponseStatistics) { DateTime requestEndTimeUtc = this.RecordHttpResponseEndTime(); - this.HttpResponseStatisticsList.Add(new HttpResponseStatistics(requestStartTimeUtc, + this.httpResponseStatistics.Add(new HttpResponseStatistics(requestStartTimeUtc, requestEndTimeUtc, request.RequestUri, request.Method, @@ -231,10 +267,10 @@ 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.httpResponseStatistics.Add(new HttpResponseStatistics(requestStartTimeUtc, requestEndTimeUtc, request.RequestUri, request.Method, diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs index a19680692d..7a9e39ad06 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(); @@ -230,7 +230,7 @@ public void Visit(ClientSideRequestStatisticsTraceDatum clientSideRequestStatist this.jsonWriter.WriteArrayEnd(); - if (clientSideRequestStatisticsTraceDatum.HttpResponseStatisticsList.Count > 0) + if (clientSideRequestStatisticsTraceDatum.HttpResponseStatisticsList.Any()) { this.jsonWriter.WriteFieldName("HttpResponseStats"); this.jsonWriter.WriteArrayStart(); 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.EmulatorTests/GatewayClientSideRequestStatsTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.EmulatorTests/GatewayClientSideRequestStatsTests.cs index ead5e42eaf..96c4d5a4de 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.EmulatorTests/GatewayClientSideRequestStatsTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.EmulatorTests/GatewayClientSideRequestStatsTests.cs @@ -5,6 +5,8 @@ namespace Microsoft.Azure.Cosmos.SDK.EmulatorTests { using System; + using System.Collections.Generic; + using System.Linq; using System.Net.Http; using System.Threading; using System.Threading.Tasks; @@ -43,9 +45,9 @@ public async Task GatewayRequestStatsTest() ItemResponse response = await this.Container.CreateItemAsync(item); ClientSideRequestStatisticsTraceDatum datum = this.GetClientSideRequestStatsFromTrace(((CosmosTraceDiagnostics)response.Diagnostics).Value, "Transport"); Assert.IsNotNull(datum.HttpResponseStatisticsList); - Assert.AreEqual(datum.HttpResponseStatisticsList.Count, 1); - Assert.IsNotNull(datum.HttpResponseStatisticsList[0].HttpResponseMessage); - Assert.AreEqual(datum.RequestEndTimeUtc, datum.HttpResponseStatisticsList[0].RequestEndTime); + Assert.AreEqual(datum.HttpResponseStatisticsList.Count(), 1); + Assert.IsNotNull(datum.HttpResponseStatisticsList.First().HttpResponseMessage); + Assert.AreEqual(datum.RequestEndTimeUtc, datum.HttpResponseStatisticsList.First().RequestEndTime); } [TestMethod] @@ -72,11 +74,17 @@ public async Task GatewayRetryRequestStatsTest(string uriToThrow, string traceTo ItemResponse response = await container.ReadItemAsync(item.id, new PartitionKey(item.pk)); ClientSideRequestStatisticsTraceDatum datum = this.GetClientSideRequestStatsFromTrace(((CosmosTraceDiagnostics)response.Diagnostics).Value, traceToFind); Assert.IsNotNull(datum.HttpResponseStatisticsList); - Assert.AreEqual(datum.HttpResponseStatisticsList.Count, expectedHttpCalls); - Assert.IsTrue(datum.HttpResponseStatisticsList[0].Exception is OperationCanceledException); - Assert.IsTrue(datum.HttpResponseStatisticsList[1].Exception is OperationCanceledException); - Assert.IsNull(datum.HttpResponseStatisticsList[2].Exception); - Assert.IsNotNull(datum.HttpResponseStatisticsList[2].HttpResponseMessage); + Assert.AreEqual(datum.HttpResponseStatisticsList.Count(), expectedHttpCalls); + + using IEnumerator list = datum.HttpResponseStatisticsList.GetEnumerator(); + + list.MoveNext(); + Assert.IsTrue(list.Current.Exception is OperationCanceledException); + list.MoveNext(); + Assert.IsTrue(list.Current.Exception is OperationCanceledException); + list.MoveNext(); + Assert.IsNull(list.Current.Exception); + Assert.IsNotNull(list.Current.HttpResponseMessage); } } @@ -93,7 +101,7 @@ public async Task RequestStatsForDirectMode() ClientSideRequestStatisticsTraceDatum datum = this.GetClientSideRequestStatsFromTrace(((CosmosTraceDiagnostics)response.Diagnostics).Value, "Transport Request"); Assert.IsNotNull(datum.HttpResponseStatisticsList); // One call for collection cache, 2 calls for PK range cache and 1 call for Address Resolution - Assert.AreEqual(datum.HttpResponseStatisticsList.Count, 4); + Assert.AreEqual(datum.HttpResponseStatisticsList.Count(), 4); } } 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..0803e8465a --- /dev/null +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs @@ -0,0 +1,155 @@ +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(10000)] + public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() + { + using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); + + ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow); + + Task backgroundTask = Task.Run(() => this.UpdateAddressesInBackground(datum, cancellationTokenSource.Token)); + + // Wait for the background thread to start + while (!datum.EndpointToAddressResolutionStatistics.Any()) + { + await Task.Delay(TimeSpan.FromMilliseconds(50)); + } + + foreach(KeyValuePair address in datum.EndpointToAddressResolutionStatistics) + { + Assert.IsNotNull(address); + } + + cancellationTokenSource.Cancel(); + } + + [TestMethod] + [Timeout(10000)] + public async Task ConcurrentUpdateHttpResponseStatisticsListTests() + { + using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); + + ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow); + + Task backgroundTask = Task.Run(() => this.UpdateHttpResponsesInBackground(datum, cancellationTokenSource.Token)); + + // Wait for the background thread to start + while (!datum.HttpResponseStatisticsList.Any()) + { + await Task.Delay(TimeSpan.FromMilliseconds(50)); + } + + foreach (ClientSideRequestStatisticsTraceDatum.HttpResponseStatistics httpResponseStatistics in datum.HttpResponseStatisticsList) + { + Assert.IsNotNull(httpResponseStatistics); + } + + cancellationTokenSource.Cancel(); + } + + [TestMethod] + [Timeout(10000)] + public async Task ConcurrentUpdateStoreResponseStatisticsListTests() + { + using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); + + ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow); + + Task backgroundTask = Task.Run(() => this.UpdateHttpResponsesInBackground(datum, cancellationTokenSource.Token)); + + // Wait for the background thread to start + while (!datum.HttpResponseStatisticsList.Any()) + { + await Task.Delay(TimeSpan.FromMilliseconds(50)); + } + + foreach (ClientSideRequestStatisticsTraceDatum.StoreResponseStatistics storeResponseStatistics in datum.StoreResponseStatisticsList) + { + Assert.IsNotNull(storeResponseStatistics); + } + + 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..5e0dfc6dc5 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 @@ -127,7 +127,7 @@ public void ValidateStoreResultSerialization() OperationType.Query, new Uri("http://someUri1.com")); - datum.StoreResponseStatisticsList.Add(storeResponseStatistics); + ((List)datum.GetType().GetField("storeResponseStatistics").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..390b39e802 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 @@ -359,7 +359,7 @@ public void TraceData() using (rootTrace = TraceForBaselineTesting.GetRootTrace()) { ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue); - + Type datumType = datum.GetType(); Uri uri1 = new Uri("http://someUri1.com"); Uri uri2 = new Uri("http://someUri2.com"); @@ -370,8 +370,9 @@ public void TraceData() DateTime.MinValue, DateTime.MaxValue, "http://localhost.com"); - datum.EndpointToAddressResolutionStatistics["asdf"] = mockStatistics; - datum.EndpointToAddressResolutionStatistics["asdf2"] = mockStatistics; + + ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf", mockStatistics); + ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf2", mockStatistics); datum.FailedReplicas.Add(uri1); datum.FailedReplicas.Add(uri2); @@ -406,7 +407,8 @@ public void TraceData() ResourceType.Document, OperationType.Query, uri1); - datum.StoreResponseStatisticsList.Add(storeResponseStatistics); + + ((List)datumType.GetField("storeResponseStatistics").GetValue(datum)).Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats", datum); } endLineNumber = GetLineNumber(); @@ -422,12 +424,9 @@ 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; + Type datumType = datum.GetType(); + ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf", default); + ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf2", default); datum.FailedReplicas.Add(default); @@ -456,11 +455,11 @@ 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); + ((List)datumType.GetField("storeResponseStatistics").GetValue(datum)).Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats Default", datum); } endLineNumber = GetLineNumber(); @@ -485,9 +484,10 @@ public void TraceData() HttpMethod.Get, ResourceType.Document, new HttpResponseMessage(System.Net.HttpStatusCode.OK) { ReasonPhrase = "Success" }, - exception: null - ); - datum.HttpResponseStatisticsList.Add(httpResponseStatistics); + exception: null); + + Type datumType = datum.GetType(); + ((List)datumType.GetField("httpResponseStatistics").GetValue(datum)).Add(httpResponseStatistics); HttpResponseStatistics httpResponseStatisticsException = new HttpResponseStatistics( DateTime.MinValue, @@ -496,9 +496,8 @@ public void TraceData() HttpMethod.Get, ResourceType.Document, responseMessage: null, - exception: new OperationCanceledException() - ); - datum.HttpResponseStatisticsList.Add(httpResponseStatisticsException); + exception: new OperationCanceledException()); + ((List)datumType.GetField("httpResponseStatistics").GetValue(datum)).Add(httpResponseStatisticsException); rootTrace.AddDatum("Client Side Request Stats", datum); } @@ -764,7 +763,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); From 054ce021992b59f587cc6c0daff685ce01840f89 Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Wed, 2 Jun 2021 18:13:55 -0700 Subject: [PATCH 02/10] Convert to use shallow copy --- .../ClientSideRequestStatisticsTraceDatum.cs | 120 ++++++++++++------ .../Tracing/TraceWriter.TraceJsonWriter.cs | 2 +- .../GatewayClientSideRequestStatsTests.cs | 26 ++-- ...entSideRequestStatisticsTraceDatumTests.cs | 63 +++++---- .../Tracing/TraceTests.cs | 2 +- .../Tracing/TraceWriterBaselineTests.cs | 26 ++-- 6 files changed, 139 insertions(+), 100 deletions(-) diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs index 66513afa9e..beaaef052a 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs @@ -13,6 +13,10 @@ namespace Microsoft.Azure.Cosmos.Tracing.TraceData internal sealed class ClientSideRequestStatisticsTraceDatum : TraceDatum, IClientSideRequestStatistics { + private static readonly IEnumerable> EmptyEndpointToAddressResolutionStatistics = new List>(); + private static readonly IReadOnlyList EmptyStoreResponseStatistics = new List(); + private static readonly IReadOnlyList EmptyHttpResponseStatistics = new List(); + private readonly object lockObject = new object(); private readonly long clientSideRequestStatisticsCreateTime; private readonly Dictionary endpointToAddressResolutionStats; @@ -20,6 +24,10 @@ internal sealed class ClientSideRequestStatisticsTraceDatum : TraceDatum, IClien private readonly List storeResponseStatistics; private readonly List httpResponseStatistics; + private IEnumerable> shallowCopyOfEndpointToAddressResolutionStatistics = null; + private IReadOnlyList shallowCopyOfStoreResponseStatistics = null; + private IReadOnlyList shallowCopyOfHttpResponseStatistics = null; + private long? firstStartRequestTimestamp; private long? lastStartRequestTimestamp; private long cumulativeEstimatedDelayDueToRateLimitingInStopwatchTicks = 0; @@ -47,12 +55,20 @@ public IEnumerable> EndpointTo { get { - lock (this.lockObject) + if (this.endpointToAddressResolutionStats.Count == 0) + { + return ClientSideRequestStatisticsTraceDatum.EmptyEndpointToAddressResolutionStatistics; + } + + lock (this.endpointToAddressResolutionStats) { - foreach (KeyValuePair a in this.endpointToAddressResolutionStats) + if (this.shallowCopyOfEndpointToAddressResolutionStatistics != null) { - yield return a; + return this.shallowCopyOfEndpointToAddressResolutionStatistics; } + + this.shallowCopyOfEndpointToAddressResolutionStatistics ??= CreateShallowCopy(this.endpointToAddressResolutionStats); + return this.shallowCopyOfEndpointToAddressResolutionStatistics; } } } @@ -65,30 +81,36 @@ public IEnumerable> EndpointTo public HashSet<(string, Uri)> RegionsContactedWithName { get; } - public IEnumerable StoreResponseStatisticsList + public IReadOnlyList StoreResponseStatisticsList { get { - lock (this.lockObject) + if (this.storeResponseStatistics.Count == 0) { - foreach (StoreResponseStatistics storeResponseStatistic in this.storeResponseStatistics) - { - yield return storeResponseStatistic; - } + return ClientSideRequestStatisticsTraceDatum.EmptyStoreResponseStatistics; + } + + lock (this.storeResponseStatistics) + { + this.shallowCopyOfStoreResponseStatistics ??= ClientSideRequestStatisticsTraceDatum.CreateShallowCopy(this.storeResponseStatistics); + return this.shallowCopyOfStoreResponseStatistics; } } } - public IEnumerable HttpResponseStatisticsList + public IReadOnlyList HttpResponseStatisticsList { get { + if (this.httpResponseStatistics.Count == 0) + { + return ClientSideRequestStatisticsTraceDatum.EmptyHttpResponseStatistics; + } + lock (this.httpResponseStatistics) { - foreach (HttpResponseStatistics httpResponseStatistic in this.httpResponseStatistics) - { - yield return httpResponseStatistic; - } + this.shallowCopyOfHttpResponseStatistics ??= ClientSideRequestStatisticsTraceDatum.CreateShallowCopy(this.httpResponseStatistics); + return this.shallowCopyOfHttpResponseStatistics; } } } @@ -127,7 +149,7 @@ public TimeSpan EstimatedClientDelayFromAllCauses public void RecordRequest(DocumentServiceRequest request) { - lock (this.lockObject) + lock (this.storeResponseStatistics) { long timestamp = Stopwatch.GetTimestamp(); if (this.received429ResponseSinceLastStartRequest) @@ -161,7 +183,7 @@ public void RecordResponse(DocumentServiceRequest request, StoreResult storeResu 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( @@ -177,18 +199,15 @@ 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)); } + // Reset the shallow copy + this.shallowCopyOfStoreResponseStatistics = null; this.storeResponseStatistics.Add(responseStatistics); if (!this.received429ResponseSinceLastStartRequest && @@ -207,8 +226,10 @@ public string RecordAddressResolutionStart(Uri targetEndpoint) endTime: DateTime.MaxValue, targetEndpoint: targetEndpoint == null ? "" : targetEndpoint.ToString()); - lock (this.lockObject) + lock (this.endpointToAddressResolutionStats) { + // Reset the shallow copy + this.shallowCopyOfEndpointToAddressResolutionStatistics = null; this.endpointToAddressResolutionStats.Add(identifier, resolutionStats); } @@ -222,21 +243,19 @@ public void RecordAddressResolutionEnd(string identifier) return; } - DateTime responseTime = DateTime.UtcNow; - lock (this.lockObject) + DateTime responseTime = this.GetAndUpdateRequestEndTime(); + + lock (this.endpointToAddressResolutionStats) { 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.endpointToAddressResolutionStats[identifier]; + // Reset the shallow copy + this.shallowCopyOfEndpointToAddressResolutionStatistics = null; this.endpointToAddressResolutionStats[identifier] = new AddressResolutionStatistics( start.StartTime, responseTime, @@ -244,14 +263,15 @@ public void RecordAddressResolutionEnd(string identifier) } } - public void RecordHttpResponse(HttpRequestMessage request, - HttpResponseMessage response, + public void RecordHttpResponse(HttpRequestMessage request, + HttpResponseMessage response, ResourceType resourceType, DateTime requestStartTimeUtc) { lock (this.httpResponseStatistics) { - DateTime requestEndTimeUtc = this.RecordHttpResponseEndTime(); + this.shallowCopyOfHttpResponseStatistics = null; + DateTime requestEndTimeUtc = this.GetAndUpdateRequestEndTime(); this.httpResponseStatistics.Add(new HttpResponseStatistics(requestStartTimeUtc, requestEndTimeUtc, request.RequestUri, @@ -269,7 +289,8 @@ public void RecordHttpException(HttpRequestMessage request, { lock (this.httpResponseStatistics) { - DateTime requestEndTimeUtc = this.RecordHttpResponseEndTime(); + this.shallowCopyOfHttpResponseStatistics = null; + DateTime requestEndTimeUtc = this.GetAndUpdateRequestEndTime(); this.httpResponseStatistics.Add(new HttpResponseStatistics(requestStartTimeUtc, requestEndTimeUtc, request.RequestUri, @@ -280,17 +301,42 @@ public void RecordHttpException(HttpRequestMessage request, } } - private DateTime RecordHttpResponseEndTime() + private DateTime GetAndUpdateRequestEndTime() { DateTime requestEndTimeUtc = DateTime.UtcNow; - if (!this.RequestEndTimeUtc.HasValue || requestEndTimeUtc > this.RequestEndTimeUtc) + lock (this.lockObject) { - this.RequestEndTimeUtc = requestEndTimeUtc; + if (!this.RequestEndTimeUtc.HasValue || requestEndTimeUtc > this.RequestEndTimeUtc) + { + this.RequestEndTimeUtc = requestEndTimeUtc; + } } return requestEndTimeUtc; } + private static IReadOnlyList CreateShallowCopy(List originalList) + { + List shallowCopy = new List(originalList.Count); + foreach (T item in originalList) + { + shallowCopy.Add(item); + } + + return shallowCopy; + } + + private static IEnumerable> CreateShallowCopy(Dictionary originalDict) + { + List> shallowCopy = new List>(originalDict.Count); + foreach (KeyValuePair item in originalDict) + { + shallowCopy.Add(item); + } + + return shallowCopy; + } + internal override void Accept(ITraceDatumVisitor traceDatumVisitor) { traceDatumVisitor.Visit(this); diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs index 7a9e39ad06..345c0d382b 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceWriter.TraceJsonWriter.cs @@ -230,7 +230,7 @@ public void Visit(ClientSideRequestStatisticsTraceDatum clientSideRequestStatist this.jsonWriter.WriteArrayEnd(); - if (clientSideRequestStatisticsTraceDatum.HttpResponseStatisticsList.Any()) + if (clientSideRequestStatisticsTraceDatum.HttpResponseStatisticsList.Count > 0) { this.jsonWriter.WriteFieldName("HttpResponseStats"); this.jsonWriter.WriteArrayStart(); diff --git a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.EmulatorTests/GatewayClientSideRequestStatsTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.EmulatorTests/GatewayClientSideRequestStatsTests.cs index 96c4d5a4de..ead5e42eaf 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.EmulatorTests/GatewayClientSideRequestStatsTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.EmulatorTests/GatewayClientSideRequestStatsTests.cs @@ -5,8 +5,6 @@ namespace Microsoft.Azure.Cosmos.SDK.EmulatorTests { using System; - using System.Collections.Generic; - using System.Linq; using System.Net.Http; using System.Threading; using System.Threading.Tasks; @@ -45,9 +43,9 @@ public async Task GatewayRequestStatsTest() ItemResponse response = await this.Container.CreateItemAsync(item); ClientSideRequestStatisticsTraceDatum datum = this.GetClientSideRequestStatsFromTrace(((CosmosTraceDiagnostics)response.Diagnostics).Value, "Transport"); Assert.IsNotNull(datum.HttpResponseStatisticsList); - Assert.AreEqual(datum.HttpResponseStatisticsList.Count(), 1); - Assert.IsNotNull(datum.HttpResponseStatisticsList.First().HttpResponseMessage); - Assert.AreEqual(datum.RequestEndTimeUtc, datum.HttpResponseStatisticsList.First().RequestEndTime); + Assert.AreEqual(datum.HttpResponseStatisticsList.Count, 1); + Assert.IsNotNull(datum.HttpResponseStatisticsList[0].HttpResponseMessage); + Assert.AreEqual(datum.RequestEndTimeUtc, datum.HttpResponseStatisticsList[0].RequestEndTime); } [TestMethod] @@ -74,17 +72,11 @@ public async Task GatewayRetryRequestStatsTest(string uriToThrow, string traceTo ItemResponse response = await container.ReadItemAsync(item.id, new PartitionKey(item.pk)); ClientSideRequestStatisticsTraceDatum datum = this.GetClientSideRequestStatsFromTrace(((CosmosTraceDiagnostics)response.Diagnostics).Value, traceToFind); Assert.IsNotNull(datum.HttpResponseStatisticsList); - Assert.AreEqual(datum.HttpResponseStatisticsList.Count(), expectedHttpCalls); - - using IEnumerator list = datum.HttpResponseStatisticsList.GetEnumerator(); - - list.MoveNext(); - Assert.IsTrue(list.Current.Exception is OperationCanceledException); - list.MoveNext(); - Assert.IsTrue(list.Current.Exception is OperationCanceledException); - list.MoveNext(); - Assert.IsNull(list.Current.Exception); - Assert.IsNotNull(list.Current.HttpResponseMessage); + Assert.AreEqual(datum.HttpResponseStatisticsList.Count, expectedHttpCalls); + Assert.IsTrue(datum.HttpResponseStatisticsList[0].Exception is OperationCanceledException); + Assert.IsTrue(datum.HttpResponseStatisticsList[1].Exception is OperationCanceledException); + Assert.IsNull(datum.HttpResponseStatisticsList[2].Exception); + Assert.IsNotNull(datum.HttpResponseStatisticsList[2].HttpResponseMessage); } } @@ -101,7 +93,7 @@ public async Task RequestStatsForDirectMode() ClientSideRequestStatisticsTraceDatum datum = this.GetClientSideRequestStatsFromTrace(((CosmosTraceDiagnostics)response.Diagnostics).Value, "Transport Request"); Assert.IsNotNull(datum.HttpResponseStatisticsList); // One call for collection cache, 2 calls for PK range cache and 1 call for Address Resolution - Assert.AreEqual(datum.HttpResponseStatisticsList.Count(), 4); + Assert.AreEqual(datum.HttpResponseStatisticsList.Count, 4); } } 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 index 0803e8465a..e4f2d14186 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs @@ -52,63 +52,58 @@ public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() Task backgroundTask = Task.Run(() => this.UpdateAddressesInBackground(datum, cancellationTokenSource.Token)); - // Wait for the background thread to start - while (!datum.EndpointToAddressResolutionStatistics.Any()) - { - await Task.Delay(TimeSpan.FromMilliseconds(50)); - } - - foreach(KeyValuePair address in datum.EndpointToAddressResolutionStatistics) - { - Assert.IsNotNull(address); - } - - cancellationTokenSource.Cancel(); + await this.ConcurrentUpdateTestHelper>( + (clientSideRequestStatistics, cancellationToken) => this.UpdateAddressesInBackground(clientSideRequestStatistics, cancellationToken), + (clientSideRequestStatistics) => clientSideRequestStatistics.EndpointToAddressResolutionStatistics); } [TestMethod] [Timeout(10000)] public async Task ConcurrentUpdateHttpResponseStatisticsListTests() { - using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); - - ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow); - - Task backgroundTask = Task.Run(() => this.UpdateHttpResponsesInBackground(datum, cancellationTokenSource.Token)); - - // Wait for the background thread to start - while (!datum.HttpResponseStatisticsList.Any()) - { - await Task.Delay(TimeSpan.FromMilliseconds(50)); - } - - foreach (ClientSideRequestStatisticsTraceDatum.HttpResponseStatistics httpResponseStatistics in datum.HttpResponseStatisticsList) - { - Assert.IsNotNull(httpResponseStatistics); - } - - cancellationTokenSource.Cancel(); + await this.ConcurrentUpdateTestHelper( + (clientSideRequestStatistics, cancellationToken) => this.UpdateHttpResponsesInBackground(clientSideRequestStatistics, cancellationToken), + (clientSideRequestStatistics) => clientSideRequestStatistics.HttpResponseStatisticsList); } [TestMethod] [Timeout(10000)] 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(() => this.UpdateHttpResponsesInBackground(datum, cancellationTokenSource.Token)); + Task backgroundTask = Task.Run(() => backgroundUpdater(datum, cancellationTokenSource.Token)); // Wait for the background thread to start - while (!datum.HttpResponseStatisticsList.Any()) + while (!getList(datum).Any()) { await Task.Delay(TimeSpan.FromMilliseconds(50)); } - foreach (ClientSideRequestStatisticsTraceDatum.StoreResponseStatistics storeResponseStatistics in datum.StoreResponseStatisticsList) + foreach (T item in getList(datum)) + { + Assert.IsNotNull(item); + } + + int count = getList(datum).Count(); + using (IEnumerator enumerator = getList(datum).GetEnumerator()) { - Assert.IsNotNull(storeResponseStatistics); + // IEnumerator should not block items being added to the list + while (getList(datum).Count() == count) + { + await Task.Delay(TimeSpan.FromMilliseconds(50)); + } } cancellationTokenSource.Cancel(); 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 5e0dfc6dc5..df479880f2 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 @@ -127,7 +127,7 @@ public void ValidateStoreResultSerialization() OperationType.Query, new Uri("http://someUri1.com")); - ((List)datum.GetType().GetField("storeResponseStatistics").GetValue(datum)).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 390b39e802..d98bd5855f 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 @@ -371,8 +371,8 @@ public void TraceData() DateTime.MaxValue, "http://localhost.com"); - ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf", mockStatistics); - ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf2", mockStatistics); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf", mockStatistics); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf2", mockStatistics); datum.FailedReplicas.Add(uri1); datum.FailedReplicas.Add(uri2); @@ -408,7 +408,7 @@ public void TraceData() OperationType.Query, uri1); - ((List)datumType.GetField("storeResponseStatistics").GetValue(datum)).Add(storeResponseStatistics); + TraceWriterBaselineTests.GetPrivateField>(datum, "storeResponseStatistics").Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats", datum); } endLineNumber = GetLineNumber(); @@ -424,9 +424,8 @@ public void TraceData() ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue); datum.ContactedReplicas.Add(default); - Type datumType = datum.GetType(); - ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf", default); - ((Dictionary)datumType.GetField("endpointToAddressResolutionStats").GetValue(datum)).Add("asdf2", default); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf", default); + TraceWriterBaselineTests.GetPrivateField>(datum, "endpointToAddressResolutionStats").Add("asdf2", default); datum.FailedReplicas.Add(default); @@ -459,7 +458,8 @@ public void TraceData() resourceType: default, operationType: default, locationEndpoint: default); - ((List)datumType.GetField("storeResponseStatistics").GetValue(datum)).Add(storeResponseStatistics); + + TraceWriterBaselineTests.GetPrivateField>(datum, "storeResponseStatistics").Add(storeResponseStatistics); rootTrace.AddDatum("Client Side Request Stats Default", datum); } endLineNumber = GetLineNumber(); @@ -486,8 +486,7 @@ public void TraceData() new HttpResponseMessage(System.Net.HttpStatusCode.OK) { ReasonPhrase = "Success" }, exception: null); - Type datumType = datum.GetType(); - ((List)datumType.GetField("httpResponseStatistics").GetValue(datum)).Add(httpResponseStatistics); + TraceWriterBaselineTests.GetPrivateField>(datum, "httpResponseStatistics").Add(httpResponseStatistics); HttpResponseStatistics httpResponseStatisticsException = new HttpResponseStatistics( DateTime.MinValue, @@ -497,7 +496,7 @@ public void TraceData() ResourceType.Document, responseMessage: null, exception: new OperationCanceledException()); - ((List)datumType.GetField("httpResponseStatistics").GetValue(datum)).Add(httpResponseStatisticsException); + TraceWriterBaselineTests.GetPrivateField>(datum, "httpResponseStatistics").Add(httpResponseStatisticsException); rootTrace.AddDatum("Client Side Request Stats", datum); } @@ -754,6 +753,13 @@ 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); + } + private static IQueryPipelineStage CreatePipeline(IDocumentContainer documentContainer, string query, int pageSize = 10, CosmosElement state = null) { TryCatch tryCreatePipeline = PipelineFactory.MonadicCreate( From 8a4213e5fc6e498cdf06839ea01d2ac17b927ba8 Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Wed, 2 Jun 2021 18:21:18 -0700 Subject: [PATCH 03/10] Removed pointless check, updated baseline --- .../ClientSideRequestStatisticsTraceDatum.cs | 5 --- .../TraceWriterBaselineTests.TraceData.xml | 34 +++++++++---------- .../Tracing/TraceWriterBaselineTests.cs | 2 +- 3 files changed, 17 insertions(+), 24 deletions(-) diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs index beaaef052a..3f0f5f4048 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs @@ -62,11 +62,6 @@ public IEnumerable> EndpointTo lock (this.endpointToAddressResolutionStats) { - if (this.shallowCopyOfEndpointToAddressResolutionStatistics != null) - { - return this.shallowCopyOfEndpointToAddressResolutionStatistics; - } - this.shallowCopyOfEndpointToAddressResolutionStatistics ??= CreateShallowCopy(this.endpointToAddressResolutionStats); return this.shallowCopyOfEndpointToAddressResolutionStatistics; } 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..f6c2bad86c 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); @@ -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,12 +419,8 @@ 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); @@ -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); } ]]> @@ -619,9 +618,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 +629,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/Tracing/TraceWriterBaselineTests.cs b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/TraceWriterBaselineTests.cs index d98bd5855f..01bc3e1aaf 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 @@ -359,7 +359,7 @@ public void TraceData() using (rootTrace = TraceForBaselineTesting.GetRootTrace()) { ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.MinValue); - Type datumType = datum.GetType(); + Uri uri1 = new Uri("http://someUri1.com"); Uri uri2 = new Uri("http://someUri2.com"); From b77c69c46ae31950ab58891b4a5cbe22243bfe98 Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Thu, 3 Jun 2021 05:06:43 -0700 Subject: [PATCH 04/10] Updates based on comments --- .../ClientSideRequestStatisticsTraceDatum.cs | 40 +++++-------------- .../Tracing/TraceWriterBaselineTests.cs | 17 +++++--- 2 files changed, 20 insertions(+), 37 deletions(-) diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs index 3f0f5f4048..c575e678cd 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs @@ -13,18 +13,18 @@ namespace Microsoft.Azure.Cosmos.Tracing.TraceData internal sealed class ClientSideRequestStatisticsTraceDatum : TraceDatum, IClientSideRequestStatistics { - private static readonly IEnumerable> EmptyEndpointToAddressResolutionStatistics = new List>(); + private static readonly IReadOnlyDictionary EmptyEndpointToAddressResolutionStatistics = new Dictionary(); private static readonly IReadOnlyList EmptyStoreResponseStatistics = new List(); private static readonly IReadOnlyList EmptyHttpResponseStatistics = new List(); - private readonly object lockObject = new object(); + 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 IEnumerable> shallowCopyOfEndpointToAddressResolutionStatistics = null; + private IReadOnlyDictionary shallowCopyOfEndpointToAddressResolutionStatistics = null; private IReadOnlyList shallowCopyOfStoreResponseStatistics = null; private IReadOnlyList shallowCopyOfHttpResponseStatistics = null; @@ -49,9 +49,9 @@ public ClientSideRequestStatisticsTraceDatum(DateTime startTime) public DateTime RequestStartTimeUtc { get; } - public DateTime? RequestEndTimeUtc { get; set; } + public DateTime? RequestEndTimeUtc { get; private set; } - public IEnumerable> EndpointToAddressResolutionStatistics + public IReadOnlyDictionary EndpointToAddressResolutionStatistics { get { @@ -62,7 +62,7 @@ public IEnumerable> EndpointTo lock (this.endpointToAddressResolutionStats) { - this.shallowCopyOfEndpointToAddressResolutionStatistics ??= CreateShallowCopy(this.endpointToAddressResolutionStats); + this.shallowCopyOfEndpointToAddressResolutionStatistics ??= new Dictionary(this.endpointToAddressResolutionStats); return this.shallowCopyOfEndpointToAddressResolutionStatistics; } } @@ -87,7 +87,7 @@ public IReadOnlyList StoreResponseStatisticsList lock (this.storeResponseStatistics) { - this.shallowCopyOfStoreResponseStatistics ??= ClientSideRequestStatisticsTraceDatum.CreateShallowCopy(this.storeResponseStatistics); + this.shallowCopyOfStoreResponseStatistics ??= new List(this.storeResponseStatistics); return this.shallowCopyOfStoreResponseStatistics; } } @@ -104,7 +104,7 @@ public IReadOnlyList HttpResponseStatisticsList lock (this.httpResponseStatistics) { - this.shallowCopyOfHttpResponseStatistics ??= ClientSideRequestStatisticsTraceDatum.CreateShallowCopy(this.httpResponseStatistics); + this.shallowCopyOfHttpResponseStatistics ??= new List(this.httpResponseStatistics); return this.shallowCopyOfHttpResponseStatistics; } } @@ -299,7 +299,7 @@ public void RecordHttpException(HttpRequestMessage request, private DateTime GetAndUpdateRequestEndTime() { DateTime requestEndTimeUtc = DateTime.UtcNow; - lock (this.lockObject) + lock (this.requestEndTimeLock) { if (!this.RequestEndTimeUtc.HasValue || requestEndTimeUtc > this.RequestEndTimeUtc) { @@ -310,28 +310,6 @@ private DateTime GetAndUpdateRequestEndTime() return requestEndTimeUtc; } - private static IReadOnlyList CreateShallowCopy(List originalList) - { - List shallowCopy = new List(originalList.Count); - foreach (T item in originalList) - { - shallowCopy.Add(item); - } - - return shallowCopy; - } - - private static IEnumerable> CreateShallowCopy(Dictionary originalDict) - { - List> shallowCopy = new List>(originalDict.Count); - foreach (KeyValuePair item in originalDict) - { - shallowCopy.Add(item); - } - - return shallowCopy; - } - internal override void Accept(ITraceDatumVisitor traceDatumVisitor) { traceDatumVisitor.Visit(this); 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 01bc3e1aaf..3e0487a503 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 @@ -380,7 +380,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, @@ -431,7 +431,7 @@ public void TraceData() datum.RegionsContactedWithName.Add(default); - datum.RequestEndTimeUtc = default; + TraceWriterBaselineTests.SetEndRequestTime(datum, default); StoreResponseStatistics storeResponseStatistics = new StoreResponseStatistics( requestStartTime: default, @@ -472,10 +472,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, @@ -760,6 +758,13 @@ internal static T GetPrivateField( return (T)datum.GetType().GetField(propertyName, BindingFlags.NonPublic | BindingFlags.Instance).GetValue(datum); } + internal static void SetEndRequestTime( + ClientSideRequestStatisticsTraceDatum datum, + DateTime dateTime) + { + datum.GetType().GetField(nameof(datum.RequestEndTimeUtc), BindingFlags.NonPublic | BindingFlags.Instance).SetValue(datum, dateTime); + } + private static IQueryPipelineStage CreatePipeline(IDocumentContainer documentContainer, string query, int pageSize = 10, CosmosElement state = null) { TryCatch tryCreatePipeline = PipelineFactory.MonadicCreate( From f9057c37c5be0f1576e87c57840aaf46fff313b7 Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Thu, 3 Jun 2021 06:46:32 -0700 Subject: [PATCH 05/10] Update baseline --- .../TraceWriterBaselineTests.TraceData.xml | 10 ++++------ .../Tracing/TraceWriterBaselineTests.cs | 4 ++-- 2 files changed, 6 insertions(+), 8 deletions(-) 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 f6c2bad86c..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 @@ -224,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, @@ -426,7 +426,7 @@ datum.RegionsContactedWithName.Add(default); - datum.RequestEndTimeUtc = default; + TraceWriterBaselineTests.SetEndRequestTime(datum, default); StoreResponseStatistics storeResponseStatistics = new StoreResponseStatistics( requestStartTime: default, @@ -606,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, 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 3e0487a503..7c23f7bacf 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 @@ -760,9 +760,9 @@ internal static T GetPrivateField( internal static void SetEndRequestTime( ClientSideRequestStatisticsTraceDatum datum, - DateTime dateTime) + DateTime? dateTime) { - datum.GetType().GetField(nameof(datum.RequestEndTimeUtc), BindingFlags.NonPublic | BindingFlags.Instance).SetValue(datum, dateTime); + datum.GetType().GetProperty("RequestEndTimeUtc").SetValue(datum, dateTime); } private static IQueryPipelineStage CreatePipeline(IDocumentContainer documentContainer, string query, int pageSize = 10, CosmosElement state = null) From 0cb0f0c81aabdc89bfac6b0292d16fcd9a1b6391 Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Thu, 3 Jun 2021 09:31:02 -0700 Subject: [PATCH 06/10] Adding more timeouts and reducing timeouts --- .../Tracing/ClientSideRequestStatisticsTraceDatumTests.cs | 6 +++--- .../Microsoft.Azure.Cosmos.Tests/Tracing/TraceTests.cs | 1 + .../Tracing/TraceWriterBaselineTests.cs | 3 +++ 3 files changed, 7 insertions(+), 3 deletions(-) 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 index e4f2d14186..22a23602db 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs @@ -43,7 +43,7 @@ public class ClientSideRequestStatisticsTraceDatumTests /// threads. It's even possible that there are background threads referencing the same instance. /// [TestMethod] - [Timeout(10000)] + [Timeout(5000)] public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() { using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); @@ -58,7 +58,7 @@ public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() } [TestMethod] - [Timeout(10000)] + [Timeout(5000)] public async Task ConcurrentUpdateHttpResponseStatisticsListTests() { await this.ConcurrentUpdateTestHelper( @@ -67,7 +67,7 @@ public async Task ConcurrentUpdateHttpResponseStatisticsListTests() } [TestMethod] - [Timeout(10000)] + [Timeout(5000)] public async Task ConcurrentUpdateStoreResponseStatisticsListTests() { await this.ConcurrentUpdateTestHelper( 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 df479880f2..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(); 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 7c23f7bacf..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(); @@ -534,6 +536,7 @@ public void TraceData() } [TestMethod] + [Timeout(5000)] public async Task ScenariosAsync() { List inputs = new List(); From 5c4387e77c94f6c633b4200c1ae31a41efccb44c Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Thu, 3 Jun 2021 09:49:24 -0700 Subject: [PATCH 07/10] Remove task delay and more timeouts --- .../GlobalPartitionEndpointManagerTests.cs | 9 +++------ .../GlobalPartitionEndpointManagerUnitTests.cs | 2 ++ 2 files changed, 5 insertions(+), 6 deletions(-) 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); From fc5e247daff8e5fddfb29e83a0f1caaed1ab1374 Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Thu, 3 Jun 2021 11:21:59 -0700 Subject: [PATCH 08/10] Commenting out tests to see if it is the cause of the timeouts --- .../ClientSideRequestStatisticsTraceDatumTests.cs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) 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 index 22a23602db..bd1d8b4c5f 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs @@ -42,8 +42,8 @@ public class ClientSideRequestStatisticsTraceDatumTests /// 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)] + //[TestMethod] + //[Timeout(5000)] public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() { using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); @@ -57,8 +57,8 @@ public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() (clientSideRequestStatistics) => clientSideRequestStatistics.EndpointToAddressResolutionStatistics); } - [TestMethod] - [Timeout(5000)] + //[TestMethod] + //[Timeout(5000)] public async Task ConcurrentUpdateHttpResponseStatisticsListTests() { await this.ConcurrentUpdateTestHelper( @@ -66,8 +66,8 @@ public async Task ConcurrentUpdateHttpResponseStatisticsListTests() (clientSideRequestStatistics) => clientSideRequestStatistics.HttpResponseStatisticsList); } - [TestMethod] - [Timeout(5000)] + //[TestMethod] + //[Timeout(5000)] public async Task ConcurrentUpdateStoreResponseStatisticsListTests() { await this.ConcurrentUpdateTestHelper( From c63bca75156c912d60d64b16179272cc8cdde4fa Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Thu, 3 Jun 2021 11:58:19 -0700 Subject: [PATCH 09/10] Adding tests back with additional checks --- ...entSideRequestStatisticsTraceDatumTests.cs | 44 ++++++++++++------- 1 file changed, 29 insertions(+), 15 deletions(-) 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 index bd1d8b4c5f..fa5534d5ba 100644 --- a/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs +++ b/Microsoft.Azure.Cosmos/tests/Microsoft.Azure.Cosmos.Tests/Tracing/ClientSideRequestStatisticsTraceDatumTests.cs @@ -42,23 +42,17 @@ public class ClientSideRequestStatisticsTraceDatumTests /// 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)] + [TestMethod] + [Timeout(5000)] public async Task ConcurrentUpdateEndpointToAddressResolutionStatisticsTests() { - using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(); - - ClientSideRequestStatisticsTraceDatum datum = new ClientSideRequestStatisticsTraceDatum(DateTime.UtcNow); - - Task backgroundTask = Task.Run(() => this.UpdateAddressesInBackground(datum, cancellationTokenSource.Token)); - await this.ConcurrentUpdateTestHelper>( (clientSideRequestStatistics, cancellationToken) => this.UpdateAddressesInBackground(clientSideRequestStatistics, cancellationToken), (clientSideRequestStatistics) => clientSideRequestStatistics.EndpointToAddressResolutionStatistics); } - //[TestMethod] - //[Timeout(5000)] + [TestMethod] + [Timeout(5000)] public async Task ConcurrentUpdateHttpResponseStatisticsListTests() { await this.ConcurrentUpdateTestHelper( @@ -66,8 +60,8 @@ public async Task ConcurrentUpdateHttpResponseStatisticsListTests() (clientSideRequestStatistics) => clientSideRequestStatistics.HttpResponseStatisticsList); } - //[TestMethod] - //[Timeout(5000)] + [TestMethod] + [Timeout(5000)] public async Task ConcurrentUpdateStoreResponseStatisticsListTests() { await this.ConcurrentUpdateTestHelper( @@ -86,11 +80,23 @@ private async Task ConcurrentUpdateTestHelper( Task backgroundTask = Task.Run(() => backgroundUpdater(datum, cancellationTokenSource.Token)); // Wait for the background thread to start - while (!getList(datum).Any()) + 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); @@ -99,11 +105,19 @@ private async Task ConcurrentUpdateTestHelper( int count = getList(datum).Count(); using (IEnumerator enumerator = getList(datum).GetEnumerator()) { - // IEnumerator should not block items being added to the list - while (getList(datum).Count() == count) + // 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(); From 5ca6865edcb061206ae6e5eb134c41f701831a14 Mon Sep 17 00:00:00 2001 From: Jake Willey Date: Thu, 3 Jun 2021 13:10:53 -0700 Subject: [PATCH 10/10] Fixed another race condition on RecordRequest. --- .../ClientSideRequestStatisticsTraceDatum.cs | 21 +++++++++++-------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs index c575e678cd..7fc0929614 100644 --- a/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs +++ b/Microsoft.Azure.Cosmos/src/Tracing/TraceData/ClientSideRequestStatisticsTraceDatum.cs @@ -144,7 +144,7 @@ public TimeSpan EstimatedClientDelayFromAllCauses public void RecordRequest(DocumentServiceRequest request) { - lock (this.storeResponseStatistics) + lock (this.recordRequestHashCodeToStartTime) { long timestamp = Stopwatch.GetTimestamp(); if (this.received429ResponseSinceLastStartRequest) @@ -160,22 +160,25 @@ 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)) - { - startDateTime = startRequestTime; - } - else + lock (this.recordRequestHashCodeToStartTime) { - 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 = this.GetAndUpdateRequestEndTime();