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 8 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
23 changes: 17 additions & 6 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,17 +50,24 @@ 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>(
Expand Down Expand Up @@ -240,7 +247,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
410 changes: 240 additions & 170 deletions ...rTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.BulkOperationsAsync.xml
View file
Open in desktop

Large diffs are not rendered by default.

72 changes: 8 additions & 64 deletions ...latorTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.ChangeFeedAsync.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1272,8 +1272,7 @@
│ │ Redacted To Not Change The Baselines From Run To Run
│ │ )
│ ├── 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
│ └── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-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 All @@ -1300,8 +1299,7 @@
│ │ Redacted To Not Change The Baselines From Run To Run
│ │ )
│ ├── 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
│ └── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-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 All @@ -1328,8 +1326,7 @@
│ │ Redacted To Not Change The Baselines From Run To Run
│ │ )
│ ├── 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
│ └── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-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 All @@ -1356,8 +1353,7 @@
│ Redacted To Not Change The Baselines From Run To Run
│ )
├── 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
└── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds
]]></Text>
<Json><![CDATA[{
"Summary": {},
Expand Down Expand Up @@ -1586,12 +1582,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
},
Expand Down Expand Up @@ -1709,12 +1699,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
},
Expand Down Expand Up @@ -1832,12 +1816,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
},
Expand Down Expand Up @@ -1955,12 +1933,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
}
Expand Down Expand Up @@ -2776,8 +2748,7 @@
│ │ Redacted To Not Change The Baselines From Run To Run
│ │ )
│ ├── 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
│ └── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-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 All @@ -2804,8 +2775,7 @@
│ │ Redacted To Not Change The Baselines From Run To Run
│ │ )
│ ├── 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
│ └── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-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 All @@ -2832,8 +2802,7 @@
│ │ Redacted To Not Change The Baselines From Run To Run
│ │ )
│ ├── 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
│ └── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-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 All @@ -2860,8 +2829,7 @@
│ Redacted To Not Change The Baselines From Run To Run
│ )
├── 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
└── Get Collection Cache(00000000-0000-0000-0000-000000000000) Routing-Component 12:00:00:000 0.00 milliseconds
]]></Text>
<Json><![CDATA[{
"Summary": {},
Expand Down Expand Up @@ -3090,12 +3058,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
},
Expand Down Expand Up @@ -3213,12 +3175,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
},
Expand Down Expand Up @@ -3336,12 +3292,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
},
Expand Down Expand Up @@ -3459,12 +3409,6 @@
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
},
{
"name": "POCO Materialization",
j82w marked this conversation as resolved.
Show resolved Hide resolved
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
}
Expand Down
46 changes: 32 additions & 14 deletions ...torTests/BaselineTest/TestBaseline/EndToEndTraceWriterBaselineTests.MiscellanousAsync.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,12 +37,13 @@
└── Microsoft.Azure.Cosmos.Handlers.RouterHandler(00000000-0000-0000-0000-000000000000) RequestHandler-Component 12:00:00:000 0.00 milliseconds
└── Microsoft.Azure.Cosmos.Handlers.TransportHandler(00000000-0000-0000-0000-000000000000) RequestHandler-Component 12:00:00:000 0.00 milliseconds
└── Microsoft.Azure.Cosmos.GatewayStoreModel Transport Request(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds
(
[Client Side Request Stats]
Redacted To Not Change The Baselines From Run To Run
[PointOperationStatisticsTraceDatum]
Redacted To Not Change The Baselines From Run To Run
)
│ (
│ [Client Side Request Stats]
│ Redacted To Not Change The Baselines From Run To Run
│ [PointOperationStatisticsTraceDatum]
│ Redacted To Not Change The Baselines From Run To Run
│ )
└── Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds
]]></Text>
<Json><![CDATA[{
"Summary": {},
Expand Down Expand Up @@ -107,7 +108,15 @@
"data": {
"Client Side Request Stats": "Redacted To Not Change The Baselines From Run To Run",
"PointOperationStatisticsTraceDatum": "Redacted To Not Change The Baselines From Run To Run"
}
},
"children": [
{
"name": "Response Serialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
}
]
}
Expand Down Expand Up @@ -154,12 +163,13 @@
└── Microsoft.Azure.Cosmos.Handlers.RouterHandler(00000000-0000-0000-0000-000000000000) RequestHandler-Component 12:00:00:000 0.00 milliseconds
└── Microsoft.Azure.Cosmos.Handlers.TransportHandler(00000000-0000-0000-0000-000000000000) RequestHandler-Component 12:00:00:000 0.00 milliseconds
└── Microsoft.Azure.Cosmos.GatewayStoreModel Transport Request(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds
(
[Client Side Request Stats]
Redacted To Not Change The Baselines From Run To Run
[PointOperationStatisticsTraceDatum]
Redacted To Not Change The Baselines From Run To Run
)
│ (
│ [Client Side Request Stats]
│ Redacted To Not Change The Baselines From Run To Run
│ [PointOperationStatisticsTraceDatum]
│ Redacted To Not Change The Baselines From Run To Run
│ )
└── Response Serialization(00000000-0000-0000-0000-000000000000) Transport-Component 12:00:00:000 0.00 milliseconds
]]></Text>
<Json><![CDATA[{
"Summary": {},
Expand Down Expand Up @@ -212,7 +222,15 @@
"data": {
"Client Side Request Stats": "Redacted To Not Change The Baselines From Run To Run",
"PointOperationStatisticsTraceDatum": "Redacted To Not Change The Baselines From Run To Run"
}
},
"children": [
{
"name": "Response Serialization",
"id": "00000000-0000-0000-0000-000000000000",
"start time": "12:00:00:000",
"duration in milliseconds": 0
}
]
}
]
}
Expand Down
Loading