Diagnostics: Adds response serialization time (#3165)

Add trace to track total serialization time in responses for additional debugging info. Fixes a bug where if a start child is called on a disposed trace which would then cause the timing to be off. It will now walk up the trace tree until it finds the active parent and add the child to that parent to keep the structure valid.
Azure · May 5, 2022 · ff88094 · ff88094
1 parent 924c2e7
commit ff88094
Show file tree

Hide file tree

Showing 12 changed files with 514 additions and 361 deletions.
diff --git a/Microsoft.Azure.Cosmos/src/Resource/CosmosResponseFactoryCore.cs b/Microsoft.Azure.Cosmos/src/Resource/CosmosResponseFactoryCore.cs
@@ -50,25 +50,35 @@ public override FeedResponse<T> CreateQueryFeedResponse<T>(
 
  private FeedResponse<T> CreateQueryFeedResponseHelper<T>(
  ResponseMessage cosmosResponseMessage)
- {
+ { 
  if (cosmosResponseMessage is QueryResponse queryResponse)
  {
- return QueryResponse<T>.CreateResponse<T>(
- cosmosQueryResponse: queryResponse,
- serializerCore: this.serializerCore);
+ using (cosmosResponseMessage.Trace.StartChild("Query Response Serialization"))
+ {
+ return QueryResponse<T>.CreateResponse<T>(
+ cosmosQueryResponse: queryResponse,
+ serializerCore: this.serializerCore);
+ }
  }
 
- return ReadFeedResponse<T>.CreateResponse<T>(
+ using (cosmosResponseMessage.Trace.StartChild("Feed Response Serialization"))
+ {
+ return ReadFeedResponse<T>.CreateResponse<T>(
  cosmosResponseMessage,
  this.serializerCore);
+ }
+
  }
 
  private FeedResponse<T> CreateChangeFeedResponseHelper<T>(
  ResponseMessage cosmosResponseMessage)
  {
- return ReadFeedResponse<T>.CreateResponse<T>(
+ using (cosmosResponseMessage.Trace.StartChild("ChangeFeed Response Serialization"))
+ {
+ return ReadFeedResponse<T>.CreateResponse<T>(
  cosmosResponseMessage,
  this.serializerCore);
+ }
  }
 
  public override ItemResponse<T> CreateItemResponse<T>(
@@ -240,7 +250,11 @@ public T ProcessMessage<T>(ResponseMessage responseMessage, Func<ResponseMessage
  //Throw the exception
  message.EnsureSuccessStatusCode();
 
- return createResponse(message);
+ using (message.Trace.StartChild("Response Serialization"))
+ {
+ return createResponse(message);
+ }
+
  }
  }
 

diff --git a/Microsoft.Azure.Cosmos/src/Resource/FeedIterators/FeedIteratorCore.cs b/Microsoft.Azure.Cosmos/src/Resource/FeedIterators/FeedIteratorCore.cs
@@ -244,10 +244,7 @@ public override async Task<FeedResponse<T>> ReadNextAsync(ITrace trace, Cancella
  }
 
  ResponseMessage response = await this.feedIterator.ReadNextAsync(trace, cancellationToken);
- using (ITrace childTrace = trace.StartChild("POCO Materialization", TraceComponent.Poco, TraceLevel.Info))
- {
- return this.responseCreator(response);
- }
+ return this.responseCreator(response);
  }
 
  protected override void Dispose(bool disposing)

diff --git a/Microsoft.Azure.Cosmos/src/Tracing/Trace.cs b/Microsoft.Azure.Cosmos/src/Tracing/Trace.cs
@@ -108,15 +108,19 @@ public ITrace StartChild(
  TraceComponent component,
  TraceLevel level)
  {
+ if (this.Parent != null && !this.stopwatch.IsRunning)
+ {
+ return this.Parent.StartChild(name, component, level);
+ }
+
  Trace child = new Trace(
  name: name,
  level: level,
  component: component,
  parent: this,
- regionContactedInternal: this.regionContactedInternal);
-
+ regionContactedInternal: this.regionContactedInternal); 
+ 
  this.AddChild(child);
-
  return child;
  }
 

diff --git a/...rTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.BulkOperationsAsync.xml b/...rTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.BulkOperationsAsync.xml
diff --git a/...latorTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.ChangeFeedAsync.xml b/...latorTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.ChangeFeedAsync.xml
@@ -1273,7 +1273,7 @@
  │ │ )
  │ ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  │ ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- │ └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ │ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  ├── Typed FeedIterator ReadNextAsync(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  │ │ (
  │ │ [Client Configuration]
@@ -1301,7 +1301,7 @@
  │ │ )
  │ ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  │ ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- │ └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ │ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  ├── Typed FeedIterator ReadNextAsync(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  │ │ (
  │ │ [Client Configuration]
@@ -1329,7 +1329,7 @@
  │ │ )
  │ ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  │ ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- │ └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ │ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  └── Typed FeedIterator ReadNextAsync(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  │ (
  │ [Client Configuration]
@@ -1357,7 +1357,7 @@
  │ )
  ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
 ]]></Text>
  <Json><![CDATA[{
  "Summary": {},
@@ -1588,7 +1588,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0
@@ -1711,7 +1711,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0
@@ -1834,7 +1834,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0
@@ -1957,7 +1957,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0
@@ -2777,7 +2777,7 @@
  │ │ )
  │ ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  │ ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- │ └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ │ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  ├── Typed FeedIterator ReadNextAsync(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  │ │ (
  │ │ [Client Configuration]
@@ -2805,7 +2805,7 @@
  │ │ )
  │ ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  │ ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- │ └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ │ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  ├── Typed FeedIterator ReadNextAsync(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  │ │ (
  │ │ [Client Configuration]
@@ -2833,7 +2833,7 @@
  │ │ )
  │ ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  │ ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- │ └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ │ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  └── Typed FeedIterator ReadNextAsync(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
  │ (
  │ [Client Configuration]
@@ -2861,7 +2861,7 @@
  │ )
  ├── Get RID(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
  ├── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds 
- └── POCO Materialization(00000000-0000-0000-0000-000000000000) Poco-Component 12:00:00:000 0.00 milliseconds 
+ └── ChangeFeed Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds 
 ]]></Text>
  <Json><![CDATA[{
  "Summary": {},
@@ -3092,7 +3092,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0
@@ -3215,7 +3215,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0
@@ -3338,7 +3338,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0
@@ -3461,7 +3461,7 @@
  "duration in milliseconds": 0
  },
  {
- "name": "POCO Materialization",
+ "name": "ChangeFeed Response Serialization",
  "id": "00000000-0000-0000-0000-000000000000",
  "start time": "12:00:00:000",
  "duration in milliseconds": 0