Skip to content

PROF-8829: Fix recording times#3891

Merged
szegedi merged 4 commits intomasterfrom
szegedi/PROF-8829-fix-recording-times
Dec 20, 2023
Merged

PROF-8829: Fix recording times#3891
szegedi merged 4 commits intomasterfrom
szegedi/PROF-8829-fix-recording-times

Conversation

@szegedi
Copy link
Copy Markdown
Contributor

@szegedi szegedi commented Dec 19, 2023

What does this PR do?

Ensures subsequent profiles are emitted with back-to-back recording timestamps. The recording end time of a profile becomes the recording start time of the next profile.

Motivation

Before this change, the recording start time of the next profile would be considered to be the instant after profiles were submitted, while the recording end of the previous one was the instant just before profiles were gathered. This would result in the time period between the two to not be considered. While most of that period is spent serializing and submitting the profile (so, it's our library code) it contains async boundaries, so other work can also get scheduled.

It doesn't matter much for flame graphs and aggregate views, but the timeline only shows events between recording start time and recording end time, so it had the potential to not display samples, GC events etc. in the first few tens(!) of milliseconds (observed between 40-70ms.)

Additional Notes

I also enhanced the timeline events profiler to use the top-level profiler provided start and end times to emit better profile duration and time data, as well as to keep late events for the next profile. This latter state should not in fact occur as long as there's only synchronous processing between _collect in profiler.js capturing new Date() for the end date and the timeline profiler generating the profile, but I figured better be safe than sorry about missing events.

Security

Datadog employees:

  • If this PR touches code that signs or publishes builds or packages, or handles credentials of any kind, I've requested a review from @DataDog/security-design-and-guidance.
  • This PR doesn't touch any of that.

@szegedi szegedi requested a review from a team as a code owner December 19, 2023 15:37
@szegedi szegedi added bug Something isn't working profiling semver-patch labels Dec 19, 2023
@github-actions
Copy link
Copy Markdown
Contributor

github-actions Bot commented Dec 19, 2023

Overall package size

Self size: 5.77 MB
Deduped: 61.88 MB
No deduping: 62.64 MB

Dependency sizes

name version self size total size
@datadog/native-iast-taint-tracking 1.6.4 16.43 MB 16.44 MB
@datadog/native-appsec 5.0.0 15.16 MB 15.17 MB
@datadog/pprof 4.1.0 9.36 MB 10.21 MB
protobufjs 7.2.5 2.77 MB 6.56 MB
@datadog/native-iast-rewriter 2.2.2 2.29 MB 2.37 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.4.1 780.32 kB 780.32 kB
import-in-the-middle 1.4.2 41.4 kB 704.79 kB
pprof-format 2.0.7 588.12 kB 588.12 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
@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
ipaddr.js 2.1.0 60.23 kB 60.23 kB
ignore 5.2.4 51.22 kB 51.22 kB
int64-buffer 0.1.10 49.18 kB 49.18 kB
istanbul-lib-coverage 3.2.0 29.34 kB 29.34 kB
lodash.uniq 4.5.0 25.01 kB 25.01 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.2 22.77 kB 22.77 kB
retry 0.13.1 18.85 kB 18.85 kB
lodash.kebabcase 4.1.1 17.75 kB 17.75 kB
node-abort-controller 3.1.1 16.89 kB 16.89 kB
lodash.pick 4.4.0 16.33 kB 16.33 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
methods 1.1.2 5.29 kB 5.29 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

@codecov
Copy link
Copy Markdown

codecov Bot commented Dec 19, 2023

Codecov Report

Attention: 6 lines in your changes are missing coverage. Please review.

Comparison is base (d8809f2) 84.60% compared to head (31bb4c1) 84.55%.
Report is 6 commits behind head on master.

Files Patch % Lines
...ackages/dd-trace/src/profiling/profilers/events.js 0.00% 6 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##           master    #3891      +/-   ##
==========================================
- Coverage   84.60%   84.55%   -0.06%     
==========================================
  Files         234      233       -1     
  Lines        9817     9713     -104     
  Branches       33       33              
==========================================
- Hits         8306     8213      -93     
+ Misses       1511     1500      -11     

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

@szegedi szegedi requested review from Qard and nsavoire December 20, 2023 10:27
@szegedi szegedi force-pushed the szegedi/PROF-8829-fix-recording-times branch from b24439e to 31bb4c1 Compare December 20, 2023 10:30
Comment thread packages/dd-trace/src/profiling/profilers/events.js
Comment thread packages/dd-trace/src/profiling/profilers/events.js
@pr-commenter
Copy link
Copy Markdown

pr-commenter Bot commented Dec 20, 2023

Benchmarks

Benchmark execution time: 2023-12-20 10:38:08

Comparing candidate commit 31bb4c1 in PR branch szegedi/PROF-8829-fix-recording-times with baseline commit d8809f2 in branch master.

Found 0 performance improvements and 0 performance regressions! Performance is the same for 520 metrics, 12 unstable metrics.

@szegedi szegedi merged commit 8e89625 into master Dec 20, 2023
@szegedi szegedi deleted the szegedi/PROF-8829-fix-recording-times branch December 20, 2023 14:39
} else {
this._profiledIntervals += 1
this._capture(this._timeoutInterval)
this._capture(this._timeoutInterval, new Date())
Copy link
Copy Markdown
Collaborator

@nsavoire nsavoire Dec 20, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It might be better to pass _lastDate here, since no new profile is started.

@nsavoire
Copy link
Copy Markdown
Collaborator

I wonder what is the impact of having inconsistent time information between pprof (timeNanos / durationNanos) and upload attributes (recording-start/end)

hoolioh pushed a commit that referenced this pull request Dec 21, 2023
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
@hoolioh hoolioh mentioned this pull request Dec 21, 2023
hoolioh pushed a commit that referenced this pull request Dec 21, 2023
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
@hoolioh hoolioh mentioned this pull request Dec 21, 2023
CarlesDD pushed a commit that referenced this pull request Dec 21, 2023
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
CarlesDD pushed a commit that referenced this pull request Dec 21, 2023
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
khanayan123 pushed a commit that referenced this pull request Jan 2, 2024
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
khanayan123 pushed a commit that referenced this pull request Jan 2, 2024
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
khanayan123 pushed a commit that referenced this pull request Jan 2, 2024
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
khanayan123 pushed a commit that referenced this pull request Jan 2, 2024
* Ensure recording start time of next profile is the same as the recording end time of the current profile.
* Pass the start-end range to profilers so they can use it
* Use passed-in start-end instead of internal duration computations
* Use end date to cut off late events for the next profile
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

bug Something isn't working profiling semver-patch

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants