Skip to content

Conversation

@nsavoire
Copy link

@nsavoirensavoire 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-commenterbot 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.

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

github-actionsbot commented Jun 16, 2023

Overall package size

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

Dependency sizes

nameversionself sizetotal size
pprof-format2.0.7588.12 kB588.12 kB
source-map0.7.4226 kB226 kB
split1.0.112.29 kB24.82 kB
p-limit3.1.07.75 kB13.78 kB
delay5.0.011.17 kB11.17 kB
pify5.0.08.87 kB8.87 kB
node-gyp-build3.9.08.81 kB8.81 kB

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

@nsavoirensavoire changed the base branch from main to szegedi/use_timestampsJune 19, 2023 14:55
@nsavoirensavoire changed the base branch from szegedi/use_timestamps to mainJune 19, 2023 14:56
@nsavoirensavoire changed the title [WIP] Test[Draft] Code hotspotsJun 19, 2023
@nsavoirensavoireforce-pushed the nsavoire/use_timestamps branch from e38f05e to 6009fcfCompareJune 19, 2023 15:11
@nsavoirensavoireforce-pushed the nsavoire/use_timestamps branch 4 times, most recently from a11552d to 522d443CompareJune 27, 2023 10:30
@nsavoirensavoire changed the title [Draft] Code hotspotsAssociate label sets with wall profilesJun 27, 2023
@nsavoirensavoire 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

@r1violletr1viollet 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

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

@r1violletr1viollet 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 freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

semver-majorTypically reserved for major breaking changes

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants

@nsavoire@theanarkh@r1viollet@szegedi