[PROF-7440] Add approximate thread state categorization for timeline #3162
Conversation
This field is set when there is a cpu+wall sample (e.g. we take both together), so I decided to rename it internally to make that clearer. I decided not to change what we emit to pprof. (This value is not currently shown in the profiling UX)
This is a refactor in preparation for introducing the new `state` label. The `state` label is different from other labels in that it will be set after looking at the thread stack. Thus, I needed a way to get more information about labels from the `ThreadContext` collector to the `Stack` collector, and thus the `sample_labels` struct was born.
**What does this PR do?** This PR adds a new feature to the Ruby profiler: thread state categorization. When taking a cpu/wall-time sample, the profiler will peek at the top of the stack, and then add a `state` label to the sample that categorizes what the thread was doing. **Motivation:** By categorizing what threads are doing when they're not on the cpu, we can synthesize nice events for timeline, e.g. paint a big rectangle when a thread was blocked on some mutex, or was waiting for the network. **Additional Notes:** Because we're matching only on "name of method at the top of the stack" + "is this method a native method" this approach is approximate, and we hope to replace it with a more accurate mechanism soon. For now, we will only expose this information as part of the timeline feature. A few tests needed to be refactored, because they assumed aggregation on the samples that they took, and the new label makes samples not aggregate some times. I considered if the tests should be changed, or the feature, but concluded that the tests were, in a sense, wrong for assuming aggregation, because in the future, we'll have timeline on by default and in such a future aggregation never happens. **How to test the change?** This change includes code coverage. You can also test it by enabling the timeline feature, and observing that the new states show up on Ruby timeline profiles (you'll need a frontend feature flag to see timeline profiles).
Sigh old Rubies :(
At least on Ruby 2.3 the `select` returned immediately, so let's use a tcp socket to get the same effect.
Compilation was failing with:
```
../../../../ext/ddtrace_profiling_native_extension/collectors_thread_context.c: In function 'trigger_sample_for_thread':
../../../../ext/ddtrace_profiling_native_extension/collectors_thread_context.c:759:5: error: missing initializer for field 'num' of 'ddog_prof_Label' [-Werror=missing-field-initializers]
759 | };
| ^
In file included from /usr/local/bundle/gems/libdatadog-4.0.0.1.0-x86_64-linux/vendor/libdatadog-4.0.0/x86_64-linux/libdatadog-x86_64-unknown-linux-gnu/lib/pkgconfig/../../include/datadog/profiling.h:12,
from ../../../../ext/ddtrace_profiling_native_extension/collectors_stack.h:3,
from ../../../../ext/ddtrace_profiling_native_extension/collectors_thread_context.c:5:
/usr/local/bundle/gems/libdatadog-4.0.0.1.0-x86_64-linux/vendor/libdatadog-4.0.0/x86_64-linux/libdatadog-x86_64-unknown-linux-gnu/lib/pkgconfig/../../include/datadog/common.h:369:11: note: 'num' declared here
369 | int64_t num;
| ^~~
cc1: all warnings being treated as errors
```
which doesn't make a lot of sense since the same pattern works for
other label initializations and doesn't generate a warning/error.
But oh well, it's easier to just make gcc happy.
Codecov Report
@@ Coverage Diff @@
## master #3162 +/- ##
========================================
Coverage 98.17% 98.18%
========================================
Files 1284 1284
Lines 73996 74116 +120
Branches 3420 3420
========================================
+ Hits 72646 72770 +124
+ Misses 1350 1346 -4
... and 2 files with indirect coverage changes 📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more |
| @@ -171,6 +178,8 @@ void sample_thread( | |||
| rb_raise(rb_eArgError, "Unexpected value for sample_type: %d", type); | |||
| } | |||
|
|
|||
| #define CHARSLICE_EQUALS(must_be_a_literal, charslice) (strlen("" must_be_a_literal) == charslice.len && strncmp(must_be_a_literal, charslice.ptr, charslice.len) == 0) | |||
There was a problem hiding this comment.
We have an explicit concat with "" in the strlen part but no such concat in the strncmp. I'd expect to need one in both places or neither, what's the deal here? 😄
There was a problem hiding this comment.
So this is a bit of C dark magic cool trick. It relies on the fact that you can do this in C:
char *foo = "hello " "world";And the result is concatenated. Note that you can only do this for literals, that is, it's not a generic way of joining strings in C.
In this case, I wanted to force the string being compared to the charslice to be a literal, so by by doing
strlen("" must_be_a_literal)
This causes the compiler to barf if you do this:
char *sleep_string = "sleep";
if (CHARSLICE_EQUALS(sleep_string, name_slice)) { Output:
../../../../ext/ddtrace_profiling_native_extension/collectors_stack.c: In function ‘sample_thread_internal’:
../../../../ext/ddtrace_profiling_native_extension/collectors_stack.c:288:30: error: expected ‘)’ before ‘sleep_string’
288 | if (CHARSLICE_EQUALS(sleep_string, name_slice)) {
| ^~~~~~~~~~~~
../../../../ext/ddtrace_profiling_native_extension/collectors_stack.c:181:67: note: in definition of macro ‘CHARSLICE_EQUALS’
181 | #define CHARSLICE_EQUALS(must_be_a_literal, charslice) (strlen("" must_be_a_literal) == charslice.len && strncmp(must_be_a_literal, charslice.ptr, charslice.len) == 0)
| ^~~~~~~~~~~~~~~~~
../../../../ext/ddtrace_profiling_native_extension/collectors_stack.c:181:63: note: to match this ‘(’
181 | #define CHARSLICE_EQUALS(must_be_a_literal, charslice) (strlen("" must_be_a_literal) == charslice.len && strncmp(must_be_a_literal, charslice.ptr, charslice.len) == 0)
| ^
../../../../ext/ddtrace_profiling_native_extension/collectors_stack.c:288:13: note: in expansion of macro ‘CHARSLICE_EQUALS’
288 | if (CHARSLICE_EQUALS(sleep_string, name_slice)) {
| ^~~~~~~~~~~~~~~~
The error could be a bit better but I hope the "must_be_a_literal" hint would lead people in the right direction ;)
I'd expect to need one in both places or neither, what's the deal here? 😄
The concat doesn't need to happen on both because "" must_be_a_literal doesn't do anything else other than cause the error to happen, and otherwise is a no-op. (Doing it on both causes more errors on the compiler side, so from that POV is even slightly worse)
As a final note, why I did this: more out of a tiny cheap micro-optimization; by forcing it to be a literal, I know the compiler can optimize away the strlen; otherwise I would probably have wanted to cache it somewhere, which would be more boilerplate.
| ) { | ||
| state_label->str = DDOG_CHARSLICE_C("blocked"); | ||
| } else if (CHARSLICE_EQUALS("wait_readable", name_slice)) { // Expected to be IO#wait_readable | ||
| state_label->str = DDOG_CHARSLICE_C("network"); |
There was a problem hiding this comment.
I assume wait_readable could also be applied to file IO. Are we heuristically setting it to network on the assumption that it should be pretty rare to manage to grab a matching sample otherwise?
There was a problem hiding this comment.
Exactly.
I'm pretty sure it's possible to do better, by looking at parts of the stack we aren't today to identify the class of instance that wait_readable is being called on, but I suspected that could be an extra can of worms (what if it's a subclass? an anonymous one? etc.) so I went with the approximation.
| // This is used to allow the `Collectors::Stack` to modify the existing label, if any. This MUST be NULL or point | ||
| // somewhere inside the labels slice above. |
There was a problem hiding this comment.
Nit: Feels a bit weird to have this "pollute" the model/prototypes when it seems to be an internal detail of sample_thread_internal. Is this done purely for performance reasons and do we think the performance impact is great (how many labels do we usually have to deal with?). Seems like we could just as easily look for the label at the time of modification (which with all the guards may not be that often anyway?).
Addendum: After progressing in the review, noticed you do have the sanity check of checking state label exists if it's a CPU/wall sample so I guess we'd be forced to look the label up for almost every sample which may justify the "caching" done here so I have less of an issue with it now and leaving this here just to make sure I understood intentions 😄
There was a problem hiding this comment.
You got it exactly right.
This label was a bit of a new thing, because up until now all labels were set by the thread context collector, and they were opaque to everyone else.
But now suddenly we have this need to have a label that shows up based on the stack, which with the current structure of the profiler happens later than all the other labels.
And yeah, this is something that will happen on every cpu/wall sample, for every thread, with the Ruby VM stopped for sampling, so it's on the hot path and thus we'd need to be careful if we wanted to abstract this to avoid overhead.
So that's why it ended up like this.
As a follow-up note, it doesn't 100% need to be like this. Currently, the array for the labels is stack allocated in the thread context collector, and it's sized to fit exactly the number of labels we need.
If we were to stop stack-allocating it, and instead had a pre-sized buffer that was a bit bigger, we could then keep a pointer to the next free element and the size of the buffer or something like that, and the stack collector could then just add the label when it wants. (Technically we could do that with the stack-allocated array, and my first prototype of this did that, but I didn't quite like how it looked)
The stack collector already has a number of such fixed buffers to store the raw stack sample it gets from the VM, and indeed in a past prototype they started as stack-allocated and then moved to reusable heap-allocated buffers.
Furthermore, if we moved more stuff away from stack allocation, we could have a bit more freedom in sequencing the operations in a sample, e.g. right now we have collectors calling each other as shown in https://github.com/DataDog/dd-trace-rb/blob/master/docs/ProfilingDevelopment.md#how-sampling-happens , but we could move to a more flat approach:
sample the_sample = ...
thread_context.add_labels(the_sample)
thread_context.add_values(the_sample)
stack.add_stack(the_sample)
...
recorder.record(the_sample)So yeah... Happy to revisit these things as you find them :)
|
Thanks Alex for the review, merging away! :) |
**What does this PR do?** This test attempts a fix to the flaky profiler tests that were added in #3162 (and that bit us in #3179). I'm not able to reproduce the issue locally, but I suspect the issue is that the spec as written was racy: 1. We start a background thread and synchronize with it via a queue 2. The thing we assert on happens AFTER the synchronization (e.g. some method called after the queue is used to signal) Thus, I suspect the issue is that once in a while, Ruby switches threads at just the wrong time: between 1 and 2, and thus our assertion fails. Instead, I've changed the specs to have a `wait_for` step that waits for the stack trace of the thread to be what we previously only assumed it to be, and only then do we run the other assertions. I call this fix "an attempt" since I wasn't able to reproduce the issue, BUT overall it's harmless: either I got it right and this fixes it for got, or I got it wrong, and we'll keep seeing the flaky specs, and I'll figure out something else to try. **Motivation:** Profiler always aims to have no flaky tests. **Additional Notes:** N/A **How to test the change?** Validate that CI is still green, and stays that way ;) Fixes DataDog/ruby-guild#53
What does this PR do?
This PR adds a new feature to the Ruby profiler: thread state categorization.
When taking a cpu/wall-time sample, the profiler will peek at the top of the stack, and then add a
statelabel to the sample that categorizes what the thread was doing.Motivation:
By categorizing what threads are doing when they're not on the cpu, we can synthesize nice events for timeline, e.g. paint a big rectangle when a thread was blocked on some mutex, or was waiting for the network.
Additional Notes:
Because we're matching only on "name of method at the top of the stack" + "is this method a native method" this approach is approximate, and we hope to replace it with a more accurate mechanism soon.
For now, we will only expose this information as part of the timeline feature.
A few tests needed to be refactored, because they assumed aggregation on the samples that they took, and the new label makes samples not aggregate some times.
I considered if the tests should be changed, or the feature, but concluded that the tests were, in a sense, wrong for assuming aggregation, because in the future, we'll have timeline on by default and in such a future aggregation never happens.
How to test the change?
This change includes code coverage. You can also test it by enabling the timeline feature, and observing that the new states show up on Ruby timeline profiles (you'll need a frontend feature flag to see timeline profiles).
For Datadog employees:
credentials of any kind, I've requested a review from
@DataDog/security-design-and-guidance.