Draft: Associate label sets with wall profiles #98

szegedi · 2023-05-15T11:05:46Z

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, as well as API to query whether labels were used when capturing a sample. In practice, the WallProfiler JS class will gain getters and setters for properties labels, a method named unsetLabels and a getter for read-only property labelsCaptured.

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 ring buffer (so allocations are avoided in the signal handler.) This happens once every 10ms while profiling. The ring buffer is sized generously, for 2x the number of samples for a single profile. This allows capturing the next profile's labels while the previous profile is post-processed.

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

Timestamp translation is necessary between V8's timestamps and libuv's high-resolution timer. The timestamps don't need to be exactly matched (and most likely won't be.) V8 uses microsecond timestamps, libuv uses nanosecond timestamps, and the bases are different. After matching the bases and scaling, the labels with closest timestamp in the ring buffer within a ±5ms range of a sample are associated with the sample.

github-actions · 2023-05-15T11:06:42Z

Overall package size

Self size: 3.2 MB
Deduped: 4.08 MB
No deduping: 4.08 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 · 2023-05-31T08:21:23Z

bindings/buffer.hh

+
+  const T& front() const { return buffer[front_index_]; }
+
+  template <typename T2>


❔ question: ‏ Why are push_back/push_front templated ?

To make their arguments universal references, so we can use std::forward

bindings/buffer.hh

nsavoire · 2023-05-31T14:41:13Z

bindings/profilers/wall.cc

+    auto newProfilers = new ProfilerMap(*currProfilers);
+    updateFn(newProfilers);
+    if (profilers.compare_exchange_weak(currProfilers, newProfilers)) {
+      delete currProfilers;


I think that at this point another thread might still reference currProfilers (eg. if it was interrupted just after line 360).
If I understand correctly, you are trying to do some kind of RCU, but I am not sure if it's feasible in userspace.

Made some changes, using atomic sets to nullptr for the sighandler to temporarily take ownership of the map while it's using it

Not sure about this, it seems that it does not solve the issue that when deleting currProfilers on line 403 another thread might be copying it on 399 because it loaded its value before CAS operation succeeded on line 401.

yep, you're right. I added a mutex to updateProfilers. It still uses the same logic to coordinate with the signal handler though. With the latest change I also accounted for the fact we can now have at most one mutator thread, so I simplified the logic around compare-and-exchange, as the once constructed new map is always valid, so we just need to try to busily install it, and don't have to loop through the whole method one more time and construct the new map again (as it'll still be based on the previous map.) Basically, there's no need for delete newProfilers anymore.

bindings/profilers/wall.cc

bindings/profilers/wall.hh

nsavoire · 2023-05-31T15:28:31Z

bindings/profilers/wall.hh

+    SampleContext() {}
+
+    SampleContext(std::shared_ptr<v8::Global<v8::Value>> l, uint64_t t)
+        : labels(l), timestamp(t) {}


Suggested change

: labels(l), timestamp(t) {}

: labels(std::move(l)), timestamp(t) {}

Hm… might it actually be even better to declare the argument as a shared_ptr&? Then it wouldn't be copied on the call site but would otherwise be fed correctly to the labels copy constructor here.

ts/src/time-profiler.ts

bindings/profilers/wall.cc

bindings/profilers/wall.hh

bindings/profilers/wall.cc

…le with labels was taken

nsavoire · 2023-06-05T08:17:50Z

bindings/profilers/wall.cc

+static void sighandler(int sig, siginfo_t* info, void* context) {
+  auto isolate = Isolate::GetCurrent();
+  WallProfiler* prof = nullptr;
+  auto prof_map = profilers.exchange(nullptr);


Very elegant solution !
This way sighandler will always be able to "lock" the map without using a mutex, nor using a CAS loop.
All the complexity / latency is moved to updateProfilers, but this is not a problem since it is rarely called.

bindings/profilers/wall.cc

nsavoire · 2023-06-05T12:36:26Z

bindings/profilers/wall.cc

+    // to it in time, and stop as soon as it sees a context that's too recent
+    // for this sample.
+    for (;;) {
+      auto contextTimestamp = sampleContext.timestamp - zeroContextTime;


contextTimestamp is an uint64_t (because sampleContext.timestamp and zeroContextTime are both uint64_t), but zeroContextTime might be bigger than sampleContext.timestamp (if a context from a previous period was not matched for example), leading to a contextTimestamp holding a very large value and test (contextTimestamp < earliest) failing whereas is should.
I find it best to avoid unsigned arithmetic types in c++, because they lead to surprising behaviours in the face of integer promotion rules (eg. -1 > 1u being true).

Our only source of unsigned ints was uv_hrtime() but fortunately we could now completely ditch it in favor of v8::base::TimeTicks so this'll no longer be an issue 🎉

…s map

… does

Make ring buffer operations interrupt safe.

szegedi · 2023-07-03T11:19:38Z

Superseded by #105

szegedi added enhancement New feature or request semver-minor Usually minor non-breaking improvements labels May 15, 2023

szegedi mentioned this pull request May 15, 2023

Associate tracing span IDs with samples in the wall profiler DataDog/dd-trace-js#3153

Closed

szegedi force-pushed the szegedi/use_timestamps branch 8 times, most recently from 88a883f to 6cb5345 Compare May 17, 2023 15:11

szegedi force-pushed the szegedi/use_timestamps branch from 7ff3d57 to 832a591 Compare May 25, 2023 12:00

szegedi requested review from nsavoire and Qard as code owners May 25, 2023 12:00

szegedi force-pushed the szegedi/use_timestamps branch 3 times, most recently from d7f74a4 to 97a6d61 Compare May 31, 2023 10:07

nsavoire reviewed May 31, 2023

View reviewed changes

nsavoire reviewed Jun 1, 2023

View reviewed changes

szegedi force-pushed the szegedi/use_timestamps branch 2 times, most recently from 56abe94 to 29e6175 Compare June 2, 2023 08:27

nsavoire and others added 3 commits June 2, 2023 11:40

Use timestamps to implement code hotspots

551b856

typo

a4fc970

Initial code for code hotspots in wall profiler

e9ecf2d

szegedi force-pushed the szegedi/use_timestamps branch 2 times, most recently from 8e2f906 to 911ff76 Compare June 2, 2023 12:54

szegedi added 3 commits June 5, 2023 09:45

Maintain profilers per isolate, in a copy-on-write style map

c63cd0c

Make labelSetsByNode per-profiler

4580483

add labelsCaptured property that can be used to detect profiling samp…

2b8e090

…le with labels was taken

szegedi force-pushed the szegedi/use_timestamps branch from 911ff76 to 547a14e Compare June 5, 2023 07:45

nsavoire reviewed Jun 5, 2023

View reviewed changes

bindings/profilers/wall.cc Outdated Show resolved Hide resolved

szegedi force-pushed the szegedi/use_timestamps branch 3 times, most recently from 5a19209 to 4a97423 Compare June 5, 2023 12:30

nsavoire reviewed Jun 5, 2023

View reviewed changes

szegedi added 4 commits June 5, 2023 18:10

Add a test + fixes for the test

cf18fc9

Suggestions from Nicolas' review, minus the atomic update of profiler…

e4b9cd6

…s map

Safe atomics for profiler map

ef46493

unsigneds are evil

6d6119a

szegedi force-pushed the szegedi/use_timestamps branch 3 times, most recently from 1a1e721 to 630d700 Compare June 9, 2023 15:51

szegedi added 4 commits June 12, 2023 16:49

Avoid the need for clock sync by ensuring we use the same clock as V8…

bf614c6

… does

Use time intervals for matching sample contexts

8fb48de

Remove CPU profiler tests. CpuProfiler causes crashes in tests, WONTFIX.

63d1245

Remove labelsCaptured logic

b5ebd13

szegedi force-pushed the szegedi/use_timestamps branch from 7a66f02 to 2bddc62 Compare June 12, 2023 14:49

szegedi added 2 commits June 12, 2023 17:36

Ensure atomic updates to labels for signal safety

bec8102

Don't use RingBuffer.push_front

cf22c9d

szegedi force-pushed the szegedi/use_timestamps branch 2 times, most recently from 3bf3471 to 8b06d8c Compare June 13, 2023 13:59

szegedi added 2 commits June 13, 2023 16:00

Move profiler start/stop/restart logic into native code.

5df66fb

Make ring buffer operations interrupt safe.

Simplify parameter extraction

42a55ad

szegedi force-pushed the szegedi/use_timestamps branch from 8b06d8c to 42a55ad Compare June 13, 2023 14:00

nsavoire mentioned this pull request Jun 19, 2023

Associate label sets with wall profiles #105

Merged

szegedi closed this Jul 3, 2023

szegedi deleted the szegedi/use_timestamps branch July 3, 2023 11:19


		const T& front() const { return buffer[front_index_]; }

		template <typename T2>

	: labels(l), timestamp(t) {}
	: labels(std::move(l)), timestamp(t) {}

Draft: Associate label sets with wall profiles #98

Draft: Associate label sets with wall profiles #98

Uh oh!

Conversation

szegedi commented May 15, 2023

Implementation notes

Timestamp matching

Uh oh!

github-actions bot commented May 15, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Overall package size

Dependency sizes

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

nsavoire Jun 5, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

szegedi commented Jul 3, 2023

Uh oh!

Uh oh!

github-actions bot commented May 15, 2023 •

edited

Loading

nsavoire Jun 5, 2023 •

edited

Loading