Fix graphql.resolve span durations

[crysmags]

What does this PR do?

This pull request closes #3925

Motivation

From PR #3925:
What does this PR do?
Fix a bug in the graphql plugin that causes all graphql.resolve spans to have incorrect durations
Motivation
When looking at APM traces for graphql requests, we noticed that the graphql.resolve spans all seem to extend until the end of the parent graphql.execute span, rather than when that field resolver actually completes. This makes it hard to identify which specific field resolvers are performance bottlenecks of a graphql query.
Example 1 - note that all graphql.resolve spans extend to roughly the same end time, even for simple fields that should be trivially fast to resolve:

Example 2 - on another, much more complex graphql query, it's even more apparent that something is wrong and causing all spans to extend until the entire graphql.execute span finishes; I would expect most of the purple bars to end earlier, and only one or a few long-tail field resolver spans would extend till the end.
Screenshot 2024-01-03 at 11 58 34 PM

Additional Notes
I believe this was a regression introduced in PR #3177, which refactored TracingPlugin subclasses to move the common span.finish() calls into the TracingPlugin base class.

However, the change to the graphql plugin's resolve operation in that PR stopped passing the finishTime argument from the finish method through to span.finish(); the base TracingPlugin.finish method does not use/accept any arguments and calls span.finish() with no args. Due to this change, span.finish() is being called without a finish time argument, and thus falls back to using the current time as the finish time.

Why does this result in all resolve spans finishing at the end of the execute span? If I'm understanding the code correctly, it looks like the graphql plugin defers finishing the resolve operations until the entire execute operation has completed - here. Although this code is still publishing the field's recorded finishTime to the finish channel, it is no longer being passed through to the span (as discussed above), so all the resolve spans are marked as finished at the current time, after the overall execute has completed.

Testing
The existing graphql plugin tests didn't appear to explicitly validate the span durations (other than a basic greater-than-zero check), so I made some guesses at how best to validate span durations within the existing test framework in order to add a unit test for this fix.

The new test introduces some new graphql field resolvers that intentionally take a while (via fake timers) to resolve:

2 async fields use setTimeout with different values to validate the duration recorded of concurrent graphql resolver promises
a 3rd new field directly ticks the clock as a synchronous resolver function to validate the duration recorded for a synchronous resolver
New test - fails as expected when run without the fix in resolve.js -- the faster async resolver's span is incorrectly recorded as taking 1234 milliseconds instead of the expected 100:
Screenshot 2024-01-05 at 10 38 37 PM

New test - passes with the changes to resolver.js:
Screenshot 2024-01-05 at 10 38 53 PM

Plugin Checklist

• Unit tests.
• TypeScript definitions.
• TypeScript tests.
• API documentation.
• CircleCI jobs/workflows.
• Plugin is exported.

Additional Notes

[github-actions]

Overall package size

Self size: 6.62 MB
Deduped: 61.88 MB
No deduping: 62.16 MB

Dependency sizes

name	version	self size	total size
@datadog/native-appsec	8.0.1	15.59 MB	15.6 MB
@datadog/native-iast-taint-tracking	2.1.0	14.91 MB	14.92 MB
@datadog/pprof	5.3.0	9.85 MB	10.22 MB
protobufjs	7.2.5	2.77 MB	6.56 MB
@datadog/native-iast-rewriter	2.3.1	2.15 MB	2.24 MB
@opentelemetry/core	1.14.0	872.87 kB	1.47 MB
@datadog/native-metrics	2.0.0	898.77 kB	1.3 MB
@opentelemetry/api	1.8.0	1.21 MB	1.21 MB
import-in-the-middle	1.7.4	70.19 kB	739.86 kB
msgpack-lite	0.1.26	201.16 kB	281.59 kB
opentracing	0.14.7	194.81 kB	194.81 kB
semver	7.5.4	93.4 kB	123.8 kB
pprof-format	2.1.0	111.69 kB	111.69 kB
@datadog/sketches-js	2.1.0	109.9 kB	109.9 kB
lodash.sortby	4.7.0	75.76 kB	75.76 kB
lru-cache	7.14.0	74.95 kB	74.95 kB
ignore	5.2.4	51.22 kB	51.22 kB
int64-buffer	0.1.10	49.18 kB	49.18 kB
shell-quote	1.8.1	44.96 kB	44.96 kB
istanbul-lib-coverage	3.2.0	29.34 kB	29.34 kB
tlhunter-sorted-set	0.1.0	24.94 kB	24.94 kB
limiter	1.1.5	23.17 kB	23.17 kB
dc-polyfill	0.1.4	23.1 kB	23.1 kB
retry	0.13.1	18.85 kB	18.85 kB
jest-docblock	29.7.0	8.99 kB	12.76 kB
crypto-randomuuid	1.0.0	11.18 kB	11.18 kB
path-to-regexp	0.1.7	6.78 kB	6.78 kB
koalas	1.0.2	6.47 kB	6.47 kB
module-details-from-path	1.0.3	4.47 kB	4.47 kB

_{🤖 This report was automatically generated by heaviest-objects-in-the-universe}

[pr-commenter]

Benchmarks

Benchmark execution time: 2024-06-07 14:21:37

Comparing candidate commit ff62ffd in PR branch crysmags/pr-3925 with baseline commit 6c43686 in branch master.

Found 1 performance improvements and 0 performance regressions! Performance is the same for 257 metrics, 8 unstable metrics.

scenario:plugin-graphql-with-depth-off-18

• 🟩 max_rss_usage [-139.114MB; -74.622MB] or [-14.707%; -7.889%]

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 80.42%. Comparing base (02dc5ce) to head (ff62ffd).
Report is 1 commits behind head on master.

Additional details and impacted files

@@             Coverage Diff             @@
##           master    #4387       +/-   ##
===========================================
+ Coverage   69.19%   80.42%   +11.23%     
===========================================
  Files           1        3        +2     
  Lines         198      373      +175     
  Branches       33       33               
===========================================
+ Hits          137      300      +163     
- Misses         61       73       +12     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[scottvanta]

Thanks @crysmags for getting the fix from #3925 merged (I was on paternity leave, so apologies for suddenly going AWOL on that PR)!

I'm a little confused by the changes to the tests though:

• a419471#diff-1ccfb4da55cff77024508ee6f36e8124522369182ed1f627e1c036d527e7e3ffL437 seems to remove validation of the span.duration field, which was the main point of the test. In the current form, it seems like the tests are only validating the order that the fields are resolved by graphql and nothing to do with the PR/fix to span.duration?
• As a minor secondary nit, it seems like slowAsyncField and fastAsyncField are now identical after those changes, so tracking them separately seems vestigial? (a419471#diff-1ccfb4da55cff77024508ee6f36e8124522369182ed1f627e1c036d527e7e3ffR91-R107)

I'm still not sure why the mocked time on my PR worked locally but not in CI, but for the sake of test coverage on span.duration, I might recommend considering the approach I originally implemented (before being asked to mock time), which uses some small delays to force/check span.duration values. i.e. essentially revert this commit back to the version on the left: 798670e