Record data-loader execution time within Apollo Tracing results#3691
Merged
Record data-loader execution time within Apollo Tracing results#3691
Conversation
github-actions
Bot
added
the
test
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
Shane32
added
enhancement
Member
Author
|
@gao-artur Let me know if you have any thoughts on this PR. I'm not sure if the result is better, or worse! |
Contributor
|
I have never used Apollo tracing and have never seen its graphical representation. But it sounds reasonable to include the DL duration in the field resolver because the field is not resolved until the DL completes. |
gao-artur
reviewed
Nov 4, 2023
|
|
||
| using (context.Metrics.Subject("field", name, metadata)) | ||
| return await next(context).ConfigureAwait(false); | ||
| var marker = context.Metrics.Subject("field", name, metadata); |
Check notice
Code scanning / CodeQL
Missed 'using' opportunity
gao-artur
approved these changes
Nov 5, 2023
Shane32
commented
Nov 5, 2023
Shane32
commented
Nov 5, 2023
Codecov Report
❗ Your organization needs to install the Codecov GitHub app to enable full functionality. @@ Coverage Diff @@
## master #3691 +/- ##
===========================================
+ Coverage 0 84.35% +84.35%
===========================================
Files 0 412 +412
Lines 0 18885 +18885
Branches 0 2964 +2964
===========================================
+ Hits 0 15930 +15930
- Misses 0 2261 +2261
- Partials 0 694 +694
|
gao-artur
reviewed
Nov 13, 2023
| // and the execution engine is not aware of which queued data loaders run as a single batch operation or not, | ||
| // making implementation difficult | ||
| [Fact] | ||
| public async Task DataLoaderTimeRecorded() |
Contributor
There was a problem hiding this comment.
This test is unstable
[xUnit.net 00:00:04.41] GraphQL.DataLoader.Tests.ApolloTracingTests.DataLoaderTimeRecorded [FAIL]
Failed GraphQL.DataLoader.Tests.ApolloTracingTests.DataLoaderTimeRecorded [2 s]
Error Message:
Shouldly.ShouldAssertException : resolverData.Duration
should be greater than or equal to
2000000000L
but was
1999818500L
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Currently a resolver's
durationproperty starts from the moment the resolver starts executing, and ends when the result is returned, even if the result is anIDataLoaderResult. It does not include the amount of time that the data loader spent executing. So, looking at trace results you can see gaps in the timeline, which is where the execution strategy executes the data loaders.This PR modifies the per-resolver instrumentation to record the duration to include up to the point in time that the data loader has finished. This means it is recording 'dead' time between the point that the resolver has finished and the point that the data loader starts. (The execution engine tries to run as many resolvers as possible before executing data loaders.) It also means that when batch data loaders are in use (the typical use case), multiple resolvers will be recording time within the
durationproperty for the execution of the same data loader.Ideally, the data loader execution time would be recorded separately, and only once for each batch data loader in use. This presents two problems: (1) the obsolete Apollo Tracing data format does not specify how to record this information, and so viewers like Playground would not be able to parse it, and (2) the execution engine is not aware of which
IDataLoaderResultinstances belong to which batch data loaders.I am hoping for some feedback before merging this PR - thanks!