Skip to content

Conversation

nsavoire
Copy link

@nsavoire nsavoire commented Jun 13, 2023

Based on #98

Adds ability to associate custom label sets to wall samples. This can then be used by dd-trace-js to associate span ids with said samples.

Implementation notes

The implementation adds JS API to set and clear labels. In practice, the WallProfiler JS class will gain getters and setters for properties labels.

Internally, the implementation uses a PPROF signal handler executing before V8's signal handler used for profiling. It will associate the current label set with a timestamp, and put it in a preallocated buffer (so allocations are avoided in the signal handler.) This happens once every 10ms while profiling. The buffer is sized generously, for 2x the number of samples for a single profile.

When the profile is post-processed once every minute, the labels are matched to samples based on the timestamp, and emitted into the serialized profile.

Timestamp matching

Two timestamps are collected in profiler signal handler and are associated with the current label: one before v8 handler is invoked and one after.
These two timestamps allow easily matching v8 profiling samples to labels, each sample is matched with the label whose timestamp interval contains the sample timestamp.
v8 does not expose publicly its clock API (v8::base::TimeTicks::Now()), matching samples / labels without a common clock source proved to be difficult, hence profiler uses private v8 API by redeclaring it.

@pr-commenter
Copy link

pr-commenter bot commented Jun 13, 2023

Benchmarks

Benchmark execution time: 2023-06-28 11:18:02

Comparing candidate commit 516a9d6 in PR branch nsavoire/use_timestamps with baseline commit 19d5e87 in branch main.

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

@nsavoire nsavoire added the semver-major Typically reserved for major breaking changes label Jun 16, 2023
@github-actions
Copy link

github-actions bot commented Jun 16, 2023

Overall package size

Self size: 2.08 MB
Deduped: 2.96 MB
No deduping: 2.96 MB

Dependency sizes

name version self size total size
pprof-format 2.0.7 588.12 kB 588.12 kB
source-map 0.7.4 226 kB 226 kB
split 1.0.1 12.29 kB 24.82 kB
p-limit 3.1.0 7.75 kB 13.78 kB
delay 5.0.0 11.17 kB 11.17 kB
pify 5.0.0 8.87 kB 8.87 kB
node-gyp-build 3.9.0 8.81 kB 8.81 kB

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

@nsavoire nsavoire changed the base branch from main to szegedi/use_timestamps June 19, 2023 14:55
@nsavoire nsavoire changed the base branch from szegedi/use_timestamps to main June 19, 2023 14:56
@nsavoire nsavoire changed the title [WIP] Test [Draft] Code hotspots Jun 19, 2023
@nsavoire nsavoire force-pushed the nsavoire/use_timestamps branch from e38f05e to 6009fcf Compare June 19, 2023 15:11
@nsavoire nsavoire requested review from szegedi, Qard and r1viollet June 20, 2023 07:48
@nsavoire nsavoire force-pushed the nsavoire/use_timestamps branch 4 times, most recently from a11552d to 522d443 Compare June 27, 2023 10:30
@nsavoire nsavoire changed the title [Draft] Code hotspots Associate label sets with wall profiles Jun 27, 2023
@nsavoire nsavoire marked this pull request as ready for review June 27, 2023 14:28
#endif

if (includeLines && withLabels) {
// Currently custom labels are not compatible with caller line

Choose a reason for hiding this comment

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

great comment, should we add a ticket to v8 for this ?

r1viollet
r1viollet previously approved these changes Jun 28, 2023
Copy link

@r1viollet r1viollet left a comment

Choose a reason for hiding this comment

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

LGTM
A very well thought approach

@nsavoire nsavoire force-pushed the nsavoire/use_timestamps branch 4 times, most recently from 48fe3e5 to dfbf67b Compare June 28, 2023 11:11
Make line number incompatible with custom labels
@nsavoire nsavoire force-pushed the nsavoire/use_timestamps branch from dfbf67b to 516a9d6 Compare June 28, 2023 11:13
Copy link

@r1viollet r1viollet left a comment

Choose a reason for hiding this comment

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

LGTM

// skip first sample because it's the one taken on profiler start, outside of
// signal handler
for (int i = 1; i < sampleCount; i++) {
// Handle out-of-order samples, hypothesis is that at most 2 consecutive

Choose a reason for hiding this comment

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

@nsavoire Hi, I want to know why this happened and why do you need to deal with this situation ? I read the V8 source code and found that the timestamp of samples is incremental (test/cctest/test-cpu-profiler.cc).

  uint64_t end_time = profile->GetEndTime();
  uint64_t current_time = profile->GetStartTime();
  CHECK_LE(current_time, end_time);
  for (int i = 0; i < profile->GetSamplesCount(); i++) {
    CHECK(profile->GetSample(i));
    uint64_t timestamp = profile->GetSampleTimestamp(i);
    // <=
    CHECK_LE(current_time, timestamp);
    CHECK_LE(timestamp, end_time);
    current_time = timestamp;
  }

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
semver-major Typically reserved for major breaking changes
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants