Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Diagnostics: Adds response serialization time #3165

Merged
merged 13 commits into from
May 5, 2022
Merged

Diagnostics: Adds response serialization time #3165

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
13 commits
Select commit Hold shift + click to select a range
5b85037
Init
Apr 25, 2022
67c1803
Add Trace to response with query serialization time and test it
Apr 28, 2022
5498436
add using statements and updated contracts
Apr 28, 2022
df718cb
address comment
Apr 29, 2022
b4117b6
Merge branch 'master' into users/jawilley/diagnostics/response
imanvt Apr 29, 2022
e0d86cf
manual update to baselines
May 3, 2022
922781e
Merge branch 'master' into users/jawilley/diagnostics/response
imanvt May 3, 2022
ad533c9
remove poco materialization trace and update contracts
May 3, 2022
fe36687
add ChangeFeed tracking
May 3, 2022
146d039
Update StartChild method to use parent trace if current trace is inac…
May 4, 2022
107283a
Merge branch 'master' into users/jawilley/diagnostics/response
imanvt May 4, 2022
b09afeb
remove unneccessary cast
May 4, 2022
b470ad0
Merge branch 'users/jawilley/diagnostics/response' of https://github.…
May 4, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
28 changes: 21 additions & 7 deletions Microsoft.Azure.Cosmos/src/Resource/CosmosResponseFactoryCore.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>(
Expand Down Expand Up @@ -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);
}

}
}

Expand Down
5 changes: 1 addition & 4 deletions Microsoft.Azure.Cosmos/src/Resource/FeedIterators/FeedIteratorCore.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
10 changes: 7 additions & 3 deletions Microsoft.Azure.Cosmos/src/Tracing/Trace.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand Down
410 changes: 240 additions & 170 deletions ...rTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.BulkOperationsAsync.xml
View file
Open in desktop

Large diffs are not rendered by default.

32 changes: 16 additions & 16 deletions ...latorTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.ChangeFeedAsync.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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": {},
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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": {},
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -3461,7 +3461,7 @@
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
j82w marked this conversation as resolved.
Show resolved Hide resolved
"name": "ChangeFeed Response Serialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
Expand Down
Loading