From e53c00ffba3f8c7498db10132b6de8e83812308c Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Mon, 2 Sep 2024 15:16:30 +0100 Subject: [PATCH 01/42] Bootstrap gvl profiling hook --- .../collectors_cpu_and_wall_time_worker.c | 35 ++++++++++++++++++- .../collectors/cpu_and_wall_time_worker.rb | 3 ++ .../collectors/cpu_and_wall_time_worker.rbs | 1 + 3 files changed, 38 insertions(+), 1 deletion(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index 9feedbf7edb..4e759b25479 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -99,6 +99,7 @@ struct cpu_and_wall_time_worker_state { bool dynamic_sampling_rate_enabled; bool allocation_profiling_enabled; bool allocation_counting_enabled; + bool gvl_profiling_enabled; bool skip_idle_samples_for_testing; VALUE self_instance; VALUE thread_context_collector_instance; @@ -122,6 +123,8 @@ struct cpu_and_wall_time_worker_state { // Used to detect/avoid nested sampling, e.g. when on_newobj_event gets triggered by a memory allocation // that happens during another sample. bool during_sample; + // Only exists when sampling is active (gets created at started and cleaned on stop) + rb_internal_thread_event_hook_t *gvl_profiling_hook; struct stats { // # Generic stats @@ -184,6 +187,7 @@ static VALUE _native_initialize( VALUE dynamic_sampling_rate_overhead_target_percentage, VALUE allocation_profiling_enabled, VALUE allocation_counting_enabled, + VALUE gvl_profiling_enabled, VALUE skip_idle_samples_for_testing ); static void cpu_and_wall_time_worker_typed_data_mark(void *state_ptr); @@ -227,6 +231,7 @@ static void delayed_error(struct cpu_and_wall_time_worker_state *state, const ch static VALUE _native_delayed_error(DDTRACE_UNUSED VALUE self, VALUE instance, VALUE error_msg); static VALUE _native_hold_signals(DDTRACE_UNUSED VALUE self); static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self); +static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused); // We're using `on_newobj_event` function with `rb_add_event_hook2`, which requires in its public signature a function // with signature `rb_event_hook_func_t` which doesn't match `on_newobj_event`. @@ -295,7 +300,7 @@ void collectors_cpu_and_wall_time_worker_init(VALUE profiling_module) { // https://bugs.ruby-lang.org/issues/18007 for a discussion around this. rb_define_alloc_func(collectors_cpu_and_wall_time_worker_class, _native_new); - rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_initialize", _native_initialize, 10); + rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_initialize", _native_initialize, 11); rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_sampling_loop", _native_sampling_loop, 1); rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_stop", _native_stop, 2); rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_reset_after_fork", _native_reset_after_fork, 1); @@ -345,6 +350,7 @@ static VALUE _native_new(VALUE klass) { state->dynamic_sampling_rate_enabled = true; state->allocation_profiling_enabled = false; state->allocation_counting_enabled = false; + state->gvl_profiling_enabled = false; state->skip_idle_samples_for_testing = false; state->thread_context_collector_instance = Qnil; state->idle_sampling_helper_instance = Qnil; @@ -357,6 +363,7 @@ static VALUE _native_new(VALUE klass) { state->stop_thread = Qnil; state->during_sample = false; + state->gvl_profiling_hook = NULL; reset_stats_not_thread_safe(state); discrete_dynamic_sampler_init(&state->allocation_sampler, "allocation", now); @@ -379,6 +386,7 @@ static VALUE _native_initialize( VALUE dynamic_sampling_rate_overhead_target_percentage, VALUE allocation_profiling_enabled, VALUE allocation_counting_enabled, + VALUE gvl_profiling_enabled, VALUE skip_idle_samples_for_testing ) { ENFORCE_BOOLEAN(gc_profiling_enabled); @@ -387,6 +395,7 @@ static VALUE _native_initialize( ENFORCE_TYPE(dynamic_sampling_rate_overhead_target_percentage, T_FLOAT); ENFORCE_BOOLEAN(allocation_profiling_enabled); ENFORCE_BOOLEAN(allocation_counting_enabled); + ENFORCE_BOOLEAN(gvl_profiling_enabled); ENFORCE_BOOLEAN(skip_idle_samples_for_testing) struct cpu_and_wall_time_worker_state *state; @@ -397,6 +406,7 @@ static VALUE _native_initialize( state->dynamic_sampling_rate_enabled = (dynamic_sampling_rate_enabled == Qtrue); state->allocation_profiling_enabled = (allocation_profiling_enabled == Qtrue); state->allocation_counting_enabled = (allocation_counting_enabled == Qtrue); + state->gvl_profiling_enabled = (gvl_profiling_enabled == Qtrue); state->skip_idle_samples_for_testing = (skip_idle_samples_for_testing == Qtrue); double total_overhead_target_percentage = NUM2DBL(dynamic_sampling_rate_overhead_target_percentage); @@ -780,6 +790,18 @@ static VALUE release_gvl_and_run_sampling_trigger_loop(VALUE instance) { RUBY_EVENT_HOOK_FLAG_SAFE | RUBY_EVENT_HOOK_FLAG_RAW_ARG) ; } + if (state->gvl_profiling_enabled) { + state->gvl_profiling_hook = rb_internal_thread_add_event_hook( + on_gvl_event, + ( + // For now we're only asking for these events, even though there's more + // (e.g. check docs or gvl-tracing gem) + RUBY_INTERNAL_THREAD_EVENT_READY /* waiting for gvl */ | + RUBY_INTERNAL_THREAD_EVENT_RESUMED /* running/runnable */ + ), + NULL + ); + } // Flag the profiler as running before we release the GVL, in case anyone's waiting to know about it rb_funcall(instance, rb_intern("signal_running"), 0); @@ -1173,7 +1195,13 @@ static void disable_tracepoints(struct cpu_and_wall_time_worker_state *state) { if (state->gc_tracepoint != Qnil) { rb_tracepoint_disable(state->gc_tracepoint); } + rb_remove_event_hook_with_data(on_newobj_event_as_hook, state->self_instance); + + if (state->gvl_profiling_hook) { + rb_internal_thread_remove_event_hook(state->gvl_profiling_hook); + state->gvl_profiling_hook = NULL; + } } static VALUE _native_with_blocked_sigprof(DDTRACE_UNUSED VALUE self) { @@ -1248,3 +1276,8 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { unblock_sigprof_signal_handler_from_running_in_current_thread(); return Qtrue; } + +static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused) { + // TODO + fprintf(stderr, "on_gvl_event %d\n", event_id); +} diff --git a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb index f77cbfd0cef..02a7c7e8c69 100644 --- a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb +++ b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb @@ -34,6 +34,8 @@ def initialize( ) end + gvl_profiling_enabled = true # TODO + self.class._native_initialize( self, thread_context_collector, @@ -44,6 +46,7 @@ def initialize( dynamic_sampling_rate_overhead_target_percentage, allocation_profiling_enabled, allocation_counting_enabled, + gvl_profiling_enabled, skip_idle_samples_for_testing, ) @worker_thread = nil diff --git a/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs b/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs index 3770a0ecd02..7e54f4eacd6 100644 --- a/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs +++ b/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs @@ -29,6 +29,7 @@ module Datadog Float dynamic_sampling_rate_overhead_target_percentage, bool allocation_profiling_enabled, bool allocation_counting_enabled, + bool gvl_profiling_enabled, bool skip_idle_samples_for_testing, ) -> true From 5a919546265d22cc35c12aec07b20aac900f52c8 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Mon, 2 Sep 2024 16:28:21 +0100 Subject: [PATCH 02/42] Added recording of when gvl waiting starts --- .../collectors_cpu_and_wall_time_worker.c | 22 ++++++++++- .../collectors_thread_context.c | 39 +++++++++++++++++++ .../collectors_thread_context.h | 2 + 3 files changed, 61 insertions(+), 2 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index 4e759b25479..c000e3919a7 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -1278,6 +1278,24 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { } static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused) { - // TODO - fprintf(stderr, "on_gvl_event %d\n", event_id); + struct cpu_and_wall_time_worker_state *state = active_sampler_instance_state; // Read from global variable, see "sampler global state safety" note above + + if (state == NULL) { + // This should not be possible; the state is only cleared AFTER we stop any active event hooks, + // and there's a lock inside the VM that prevents concurrent in clearing and executing hooks + // (so there can't be a hook that started executing while another thread was stopping and cleaning up) + fprintf(stderr, "[ddtrace] Unexpected missing state in on_gvl_event (%d)\n", event_id); + return; + } + + VALUE current_thread = event_data->thread; + + if (event_id == RUBY_INTERNAL_THREAD_EVENT_READY) { /* waiting for gvl */ + thread_context_collector_on_gvl_waiting(current_thread); + } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ + thread_context_collector_on_gvl_running(state->thread_context_collector_instance, current_thread); + } else { + // This is a very delicate time and it's hard for us to raise an exception so let's at least complain to stderr + fprintf(stderr, "[ddtrace] Unexpected value in on_gvl_event (%d)\n", event_id); + } } diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 9cee298c08b..bf6900a4d91 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -1,4 +1,5 @@ #include +#include #include "collectors_thread_context.h" #include "clock_id.h" @@ -86,6 +87,8 @@ static ID at_otel_values_id; // id of :@otel_values in Ruby static ID at_parent_span_id_id; // id of :@parent_span_id in Ruby static ID at_datadog_trace_id; // id of :@datadog_trace in Ruby +static rb_internal_thread_specific_key_t per_thread_gvl_waiting_timestamp_key; + // Contains state for a single ThreadContext instance struct thread_context_collector_state { // Note: Places in this file that usually need to be changed when this struct is changed are tagged with @@ -279,6 +282,8 @@ void collectors_thread_context_init(VALUE profiling_module) { at_parent_span_id_id = rb_intern_const("@parent_span_id"); at_datadog_trace_id = rb_intern_const("@datadog_trace"); + per_thread_gvl_waiting_timestamp_key = rb_internal_thread_specific_key_create(); + gc_profiling_init(); } @@ -946,6 +951,17 @@ static void initialize_context(VALUE thread, struct per_thread_context *thread_c // These will only be used during a GC operation thread_context->gc_tracking.cpu_time_at_start_ns = INVALID_TIME; thread_context->gc_tracking.wall_time_at_start_ns = INVALID_TIME; + + // We use this special location to store data that can be accessed without any + // kind of synchronization (e.g. by threads without the GVL). + // + // We clear it here to make sure there's no stale data from a previous execution + // of the profiler. + // + // (Clearing this is potentially a race, but what we want is to avoid _stale_ data, so + // if this gets set concurrently with context initialization, then such setting belongs + // to the current profiler instance, so that's OK) + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, NULL); } static void free_context(struct per_thread_context* thread_context) { @@ -1474,3 +1490,26 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self thread_context_collector_sample_skipped_allocation_samples(collector_instance, NUM2UINT(skipped_samples)); return Qtrue; } + +// This function gets called from a thread that is NOT holding the GVL +void thread_context_collector_on_gvl_waiting(VALUE thread) { + // Because this function gets called from a thread that is NOT holding the GVL, we avoid touching the + // per-thread context directly. + // + // Instead, we ask Ruby to hold the data we need in Ruby's own special per-thread context area + long current_monotonic_wall_time_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE); + + if (current_monotonic_wall_time_ns <= 0 && ((unsigned long) current_monotonic_wall_time_ns) > UINTPTR_MAX) return; + + uintptr_t gvl_waiting_at = current_monotonic_wall_time_ns; + + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) gvl_waiting_at); +} + +void thread_context_collector_on_gvl_running(VALUE self_instance, VALUE thread) { + struct thread_context_collector_state *state; + if (!rb_typeddata_is_kind_of(self_instance, &thread_context_collector_typed_data)) return; + // This should never fail the the above check passes + TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); + +} diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.h b/ext/datadog_profiling_native_extension/collectors_thread_context.h index 073c1caa911..6184f7da1b4 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.h +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.h @@ -14,3 +14,5 @@ VALUE thread_context_collector_sample_after_gc(VALUE self_instance); void thread_context_collector_on_gc_start(VALUE self_instance); bool thread_context_collector_on_gc_finish(VALUE self_instance); VALUE enforce_thread_context_collector_instance(VALUE object); +void thread_context_collector_on_gvl_waiting(VALUE thread); +void thread_context_collector_on_gvl_running(VALUE self_instance, VALUE thread); From 1ee127fa26a61f72197019cc80e294cec37cad46 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Mon, 2 Sep 2024 17:25:48 +0100 Subject: [PATCH 03/42] Track waiting on GVL state in thread specific variables and trigger sampling --- .../collectors_cpu_and_wall_time_worker.c | 14 ++---- .../collectors_thread_context.c | 49 +++++++++++++------ .../collectors_thread_context.h | 4 +- 3 files changed, 39 insertions(+), 28 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index c000e3919a7..abf80edbe16 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -1278,22 +1278,16 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { } static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused) { - struct cpu_and_wall_time_worker_state *state = active_sampler_instance_state; // Read from global variable, see "sampler global state safety" note above - - if (state == NULL) { - // This should not be possible; the state is only cleared AFTER we stop any active event hooks, - // and there's a lock inside the VM that prevents concurrent in clearing and executing hooks - // (so there can't be a hook that started executing while another thread was stopping and cleaning up) - fprintf(stderr, "[ddtrace] Unexpected missing state in on_gvl_event (%d)\n", event_id); - return; - } + // Be very careful about touching the `state` here or doing anything at all: + // This function gets called even without the GVL, and even from background Ractors! VALUE current_thread = event_data->thread; if (event_id == RUBY_INTERNAL_THREAD_EVENT_READY) { /* waiting for gvl */ thread_context_collector_on_gvl_waiting(current_thread); } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ - thread_context_collector_on_gvl_running(state->thread_context_collector_instance, current_thread); + bool should_sample = thread_context_collector_on_gvl_running(current_thread); + if (should_sample) rb_postponed_job_trigger(FIXME); } else { // This is a very delicate time and it's hard for us to raise an exception so let's at least complain to stderr fprintf(stderr, "[ddtrace] Unexpected value in on_gvl_event (%d)\n", event_id); diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index bf6900a4d91..464a1e7f2fd 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -77,6 +77,11 @@ #define MISSING_TRACER_CONTEXT_KEY 0 #define TIME_BETWEEN_GC_EVENTS_NS MILLIS_AS_NS(10) +// This is used as a placeholder to mark threads that are allowed to be profiled (enabled) +// (e.g. to avoid trying to gvl profile threads that are not from the main Ractor) +// and for which there's no data yet +#define GVL_WAITING_ENABLED_EMPTY UINTPTR_MAX + static ID at_active_span_id; // id of :@active_span in Ruby static ID at_active_trace_id; // id of :@active_trace in Ruby static ID at_id_id; // id of :@id in Ruby @@ -438,7 +443,7 @@ static VALUE _native_on_gc_start(DDTRACE_UNUSED VALUE self, VALUE collector_inst // This method exists only to enable testing Datadog::Profiling::Collectors::ThreadContext behavior using RSpec. // It SHOULD NOT be used for other purposes. static VALUE _native_on_gc_finish(DDTRACE_UNUSED VALUE self, VALUE collector_instance) { - thread_context_collector_on_gc_finish(collector_instance); + (void) thread_context_collector_on_gc_finish(collector_instance); return Qtrue; } @@ -597,6 +602,7 @@ void thread_context_collector_on_gc_start(VALUE self_instance) { // // Assumption 1: This function is called in a thread that is holding the Global VM Lock. Caller is responsible for enforcing this. // Assumption 2: This function is called from the main Ractor (if Ruby has support for Ractors). +__attribute__((warn_unused_result)) bool thread_context_collector_on_gc_finish(VALUE self_instance) { struct thread_context_collector_state *state; if (!rb_typeddata_is_kind_of(self_instance, &thread_context_collector_typed_data)) return false; @@ -955,13 +961,14 @@ static void initialize_context(VALUE thread, struct per_thread_context *thread_c // We use this special location to store data that can be accessed without any // kind of synchronization (e.g. by threads without the GVL). // - // We clear it here to make sure there's no stale data from a previous execution - // of the profiler. + // We set this marker here for two purposes: + // * To make sure there's no stale data from a previous execution of the profiler. + // * To mark threads that are actually being profiled // - // (Clearing this is potentially a race, but what we want is to avoid _stale_ data, so - // if this gets set concurrently with context initialization, then such setting belongs + // (Setting this is potentially a race, but what we want is to avoid _stale_ data, so + // if this gets set concurrently with context initialization, then such a value will belong // to the current profiler instance, so that's OK) - rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, NULL); + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); } static void free_context(struct per_thread_context* thread_context) { @@ -1491,25 +1498,35 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return Qtrue; } -// This function gets called from a thread that is NOT holding the GVL +// This function can get called from outside the GVL and even on non-main Ractors void thread_context_collector_on_gvl_waiting(VALUE thread) { // Because this function gets called from a thread that is NOT holding the GVL, we avoid touching the // per-thread context directly. // // Instead, we ask Ruby to hold the data we need in Ruby's own special per-thread context area - long current_monotonic_wall_time_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE); + // + // Also, this function can get called on the non-main Ractor. We deal with this by checking if the value in the context + // is non-zero, since only `initialize_context` ever sets the value from 0 to non-zero for threads it sees. + uintptr_t thread_being_profiled = (uintptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); + if (!thread_being_profiled) return; + long current_monotonic_wall_time_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE); if (current_monotonic_wall_time_ns <= 0 && ((unsigned long) current_monotonic_wall_time_ns) > UINTPTR_MAX) return; - uintptr_t gvl_waiting_at = current_monotonic_wall_time_ns; - - rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) gvl_waiting_at); + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) current_monotonic_wall_time_ns); } -void thread_context_collector_on_gvl_running(VALUE self_instance, VALUE thread) { - struct thread_context_collector_state *state; - if (!rb_typeddata_is_kind_of(self_instance, &thread_context_collector_typed_data)) return; - // This should never fail the the above check passes - TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); +#define WAITING_FOR_GVL_THRESHOLD_NS MILLIS_AS_NS(10) + +// This function can get called from outside the GVL and even on non-main Ractors +__attribute__((warn_unused_result)) +bool thread_context_collector_on_gvl_running(VALUE thread) { + uintptr_t gvl_waiting_at = (uintptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); + + // Thread was not being profiled / not waiting on gvl + if (gvl_waiting_at == 0 || gvl_waiting_at == GVL_WAITING_ENABLED_EMPTY) return false; + + long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - wall_time_at_start_ns; + return waiting_for_gvl_duration_ns >= WAITING_FOR_GVL_THRESHOLD_NS; } diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.h b/ext/datadog_profiling_native_extension/collectors_thread_context.h index 6184f7da1b4..013e84d6b93 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.h +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.h @@ -12,7 +12,7 @@ void thread_context_collector_sample_allocation(VALUE self_instance, unsigned in void thread_context_collector_sample_skipped_allocation_samples(VALUE self_instance, unsigned int skipped_samples); VALUE thread_context_collector_sample_after_gc(VALUE self_instance); void thread_context_collector_on_gc_start(VALUE self_instance); -bool thread_context_collector_on_gc_finish(VALUE self_instance); +__attribute__((warn_unused_result)) bool thread_context_collector_on_gc_finish(VALUE self_instance); VALUE enforce_thread_context_collector_instance(VALUE object); void thread_context_collector_on_gvl_waiting(VALUE thread); -void thread_context_collector_on_gvl_running(VALUE self_instance, VALUE thread); +__attribute__((warn_unused_result)) bool thread_context_collector_on_gvl_running(VALUE thread); From f5bcd4fac6e8cabfc78d40d9c74886e0d6f40269 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Tue, 3 Sep 2024 10:28:34 +0100 Subject: [PATCH 04/42] Wire up postponed job execution --- .../collectors_cpu_and_wall_time_worker.c | 15 +++++++++++++-- .../collectors_thread_context.c | 4 ++-- 2 files changed, 15 insertions(+), 4 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index abf80edbe16..5fc118e6fe4 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -88,6 +88,7 @@ unsigned int MAX_ALLOC_WEIGHT = 10000; // `collectors_cpu_and_wall_time_worker_init` below and always get reused after that. static rb_postponed_job_handle_t sample_from_postponed_job_handle; static rb_postponed_job_handle_t after_gc_from_postponed_job_handle; + static rb_postponed_job_handle_t after_gvl_running_from_postponed_job_handle; #endif // Contains state for a single CpuAndWallTimeWorker instance @@ -232,6 +233,7 @@ static VALUE _native_delayed_error(DDTRACE_UNUSED VALUE self, VALUE instance, VA static VALUE _native_hold_signals(DDTRACE_UNUSED VALUE self); static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self); static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused); +static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused); // We're using `on_newobj_event` function with `rb_add_event_hook2`, which requires in its public signature a function // with signature `rb_event_hook_func_t` which doesn't match `on_newobj_event`. @@ -277,8 +279,13 @@ void collectors_cpu_and_wall_time_worker_init(VALUE profiling_module) { int unused_flags = 0; sample_from_postponed_job_handle = rb_postponed_job_preregister(unused_flags, sample_from_postponed_job, NULL); after_gc_from_postponed_job_handle = rb_postponed_job_preregister(unused_flags, after_gc_from_postponed_job, NULL); + after_gvl_running_from_postponed_job_handle = rb_postponed_job_preregister(unused_flags, after_gvl_running_from_postponed_job, NULL); - if (sample_from_postponed_job_handle == POSTPONED_JOB_HANDLE_INVALID || after_gc_from_postponed_job_handle == POSTPONED_JOB_HANDLE_INVALID) { + if ( + sample_from_postponed_job_handle == POSTPONED_JOB_HANDLE_INVALID || + after_gc_from_postponed_job_handle == POSTPONED_JOB_HANDLE_INVALID || + after_gvl_running_from_postponed_job_handle == POSTPONED_JOB_HANDLE_INVALID + ) { rb_raise(rb_eRuntimeError, "Failed to register profiler postponed jobs (got POSTPONED_JOB_HANDLE_INVALID)"); } #else @@ -1287,9 +1294,13 @@ static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_even thread_context_collector_on_gvl_waiting(current_thread); } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ bool should_sample = thread_context_collector_on_gvl_running(current_thread); - if (should_sample) rb_postponed_job_trigger(FIXME); + if (should_sample) rb_postponed_job_trigger(after_gvl_running_from_postponed_job_handle); } else { // This is a very delicate time and it's hard for us to raise an exception so let's at least complain to stderr fprintf(stderr, "[ddtrace] Unexpected value in on_gvl_event (%d)\n", event_id); } } + +static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused) { + fprintf(stderr, "After gvl running!\n"); +} diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 464a1e7f2fd..d035ca145e3 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -443,7 +443,7 @@ static VALUE _native_on_gc_start(DDTRACE_UNUSED VALUE self, VALUE collector_inst // This method exists only to enable testing Datadog::Profiling::Collectors::ThreadContext behavior using RSpec. // It SHOULD NOT be used for other purposes. static VALUE _native_on_gc_finish(DDTRACE_UNUSED VALUE self, VALUE collector_instance) { - (void) thread_context_collector_on_gc_finish(collector_instance); + (void) !thread_context_collector_on_gc_finish(collector_instance); return Qtrue; } @@ -1526,7 +1526,7 @@ bool thread_context_collector_on_gvl_running(VALUE thread) { // Thread was not being profiled / not waiting on gvl if (gvl_waiting_at == 0 || gvl_waiting_at == GVL_WAITING_ENABLED_EMPTY) return false; - long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - wall_time_at_start_ns; + long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - gvl_waiting_at; return waiting_for_gvl_duration_ns >= WAITING_FOR_GVL_THRESHOLD_NS; } From 31ce66dc75ca0b31fdd3ab7910666a239b12e9b3 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Tue, 3 Sep 2024 17:27:47 +0100 Subject: [PATCH 05/42] Still figuring out how to handle sampling of threads after waiting on gvl --- .../collectors_cpu_and_wall_time_worker.c | 18 ++++- .../collectors_thread_context.c | 67 +++++++++++++++++-- .../collectors_thread_context.h | 1 + 3 files changed, 78 insertions(+), 8 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index 5fc118e6fe4..ab3cba8e788 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -921,7 +921,6 @@ static void after_gc_from_postponed_job(DDTRACE_UNUSED void *_unused) { state->during_sample = true; - // Trigger sampling using the Collectors::ThreadState; rescue against any exceptions that happen during sampling safely_call(thread_context_collector_sample_after_gc, state->thread_context_collector_instance, state->self_instance); state->during_sample = false; @@ -1294,7 +1293,11 @@ static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_even thread_context_collector_on_gvl_waiting(current_thread); } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ bool should_sample = thread_context_collector_on_gvl_running(current_thread); - if (should_sample) rb_postponed_job_trigger(after_gvl_running_from_postponed_job_handle); + + if (should_sample) { + // should_sample is only true if a thread belongs to the main Ractor, so we're good to go + rb_postponed_job_trigger(after_gvl_running_from_postponed_job_handle); + } } else { // This is a very delicate time and it's hard for us to raise an exception so let's at least complain to stderr fprintf(stderr, "[ddtrace] Unexpected value in on_gvl_event (%d)\n", event_id); @@ -1302,5 +1305,14 @@ static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_even } static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused) { - fprintf(stderr, "After gvl running!\n"); + struct cpu_and_wall_time_worker_state *state = active_sampler_instance_state; // Read from global variable, see "sampler global state safety" note above + + // This can potentially happen if the CpuAndWallTimeWorker was stopped while the postponed job was waiting to be executed; nothing to do + if (state == NULL) return; + + state->during_sample = true; + + safely_call(thread_context_collector_sample_after_gvl_running, state->thread_context_collector_instance, state->self_instance); + + state->during_sample = false; } diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index d035ca145e3..05f5b86f0f9 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -80,7 +80,7 @@ // This is used as a placeholder to mark threads that are allowed to be profiled (enabled) // (e.g. to avoid trying to gvl profile threads that are not from the main Ractor) // and for which there's no data yet -#define GVL_WAITING_ENABLED_EMPTY UINTPTR_MAX +#define GVL_WAITING_ENABLED_EMPTY INTPTR_MAX static ID at_active_span_id; // id of :@active_span in Ruby static ID at_active_trace_id; // id of :@active_trace in Ruby @@ -536,6 +536,13 @@ void update_metrics_and_sample( thread_context->gc_tracking.cpu_time_at_start_ns, IS_NOT_WALL_TIME ); + + // TODO: This feels like a hack here -- is there a better place to do this? + intptr_t gvl_waiting_at = (intptr_t) rb_thread_local_variable_get(thread_being_sampled, per_thread_gvl_waiting_timestamp_key); + if (gvl_waiting_at != 0 && gvl_waiting_at != GVL_WAITING_ENABLED_EMPTY) { + // TODO: Was here + } + long wall_time_elapsed_ns = update_time_since_previous_sample( &thread_context->wall_time_at_previous_sample_ns, current_monotonic_wall_time_ns, @@ -1507,11 +1514,11 @@ void thread_context_collector_on_gvl_waiting(VALUE thread) { // // Also, this function can get called on the non-main Ractor. We deal with this by checking if the value in the context // is non-zero, since only `initialize_context` ever sets the value from 0 to non-zero for threads it sees. - uintptr_t thread_being_profiled = (uintptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); + intptr_t thread_being_profiled = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); if (!thread_being_profiled) return; long current_monotonic_wall_time_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE); - if (current_monotonic_wall_time_ns <= 0 && ((unsigned long) current_monotonic_wall_time_ns) > UINTPTR_MAX) return; + if (current_monotonic_wall_time_ns <= 0 || current_monotonic_wall_time_ns > GVL_WAITING_ENABLED_EMPTY) return; rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) current_monotonic_wall_time_ns); } @@ -1521,12 +1528,62 @@ void thread_context_collector_on_gvl_waiting(VALUE thread) { // This function can get called from outside the GVL and even on non-main Ractors __attribute__((warn_unused_result)) bool thread_context_collector_on_gvl_running(VALUE thread) { - uintptr_t gvl_waiting_at = (uintptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); // Thread was not being profiled / not waiting on gvl if (gvl_waiting_at == 0 || gvl_waiting_at == GVL_WAITING_ENABLED_EMPTY) return false; + // @ivoanjo: I'm not sure if this can happen -- It means we should've sampled already but didn't + if (gvl_waiting_at < 0) return true; + long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - gvl_waiting_at; - return waiting_for_gvl_duration_ns >= WAITING_FOR_GVL_THRESHOLD_NS; + bool should_sample = waiting_for_gvl_duration_ns >= WAITING_FOR_GVL_THRESHOLD_NS; + + if (should_sample) { + // We flip the gvl_waiting_at to negative to mark that the thread is now running + intptr_t gvl_waiting_at_is_now_running = -gvl_waiting_at; + + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) gvl_waiting_at_is_now_running); + } else { + // We decided not to sample. Let's mark the thread back to being profiled, but having no data yet. + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + } + + return should_sample; +} + +VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { + struct thread_context_collector_state *state; + TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); + + if (!state->timeline_enabled) rb_raise(rb_eRuntimeError, "gvl profiling requires timeline to be enabled"); + + VALUE current_thread = rb_thread_current(); + struct per_thread_context *thread_context = get_or_create_context_for(thread, state); + + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(current_thread, per_thread_gvl_waiting_timestamp_key); + + if (gvl_waiting_at >= 0) { + // @ivoanjo: I'm not sure if this can ever happen. This means that we're not on the same thread + // that ran `thread_context_collector_on_gvl_running` and made the decision to sample. + // We do nothing in this case. + return Qnil; + } + + // The timestamp is encoded as a negative value in thread_context_collector_on_gvl_running + long gvl_waiting_wall_time_ns = -gvl_waiting_at; + + // Wrong + update_metrics_and_sample( + state, + /* thread_being_sampled: */ thread, + /* stack_from_thread: */ thread, + thread_context, + thread_context->sampling_buffer, + FIXME, + FIXME + ); + + return Qnil; // To allow this to be called from rb_rescue2 } diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.h b/ext/datadog_profiling_native_extension/collectors_thread_context.h index 013e84d6b93..52ce051c74b 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.h +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.h @@ -16,3 +16,4 @@ __attribute__((warn_unused_result)) bool thread_context_collector_on_gc_finish(V VALUE enforce_thread_context_collector_instance(VALUE object); void thread_context_collector_on_gvl_waiting(VALUE thread); __attribute__((warn_unused_result)) bool thread_context_collector_on_gvl_running(VALUE thread); +VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance); From 2f3dd9717d15bada5fc10dcb2e5e8f3b070e8a0b Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 6 Sep 2024 09:18:21 +0100 Subject: [PATCH 06/42] Wire up waiting for gvl sampling, still missing actually attaching the state --- .../collectors_thread_context.c | 134 +++++++++++++++--- .../stack_recorder.h | 2 + .../collectors/cpu_and_wall_time_worker.rb | 2 +- 3 files changed, 115 insertions(+), 23 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 05f5b86f0f9..51c492debd2 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -191,7 +191,7 @@ static VALUE _native_sample(VALUE self, VALUE collector_instance, VALUE profiler static VALUE _native_on_gc_start(VALUE self, VALUE collector_instance); static VALUE _native_on_gc_finish(VALUE self, VALUE collector_instance); static VALUE _native_sample_after_gc(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE reset_monotonic_to_system_state); -void update_metrics_and_sample( +static void update_metrics_and_sample( struct thread_context_collector_state *state, VALUE thread_being_sampled, VALUE stack_from_thread, @@ -209,7 +209,8 @@ static void trigger_sample_for_thread( sample_values values, long current_monotonic_wall_time_ns, ddog_CharSlice *ruby_vm_type, - ddog_CharSlice *class_name + ddog_CharSlice *class_name, + bool is_gvl_waiting_state ); static VALUE _native_thread_list(VALUE self); static struct per_thread_context *get_or_create_context_for(VALUE thread, struct thread_context_collector_state *state); @@ -521,7 +522,7 @@ void thread_context_collector_sample(VALUE self_instance, long current_monotonic ); } -void update_metrics_and_sample( +static void update_metrics_and_sample( struct thread_context_collector_state *state, VALUE thread_being_sampled, VALUE stack_from_thread, // This can be different when attributing profiler overhead using a different stack @@ -530,19 +531,98 @@ void update_metrics_and_sample( long current_cpu_time_ns, long current_monotonic_wall_time_ns ) { - long cpu_time_elapsed_ns = update_time_since_previous_sample( + // TODO: This feels like a hack here -- is there a better place to do this? + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread_being_sampled, per_thread_gvl_waiting_timestamp_key); + + // We can be in one of 2 situations here: + // + // 1. The current sample is the first one after we entered the Waiting for GVL state + // (wall_time_at_previous_sample_ns < abs(gvl_waiting_at)) + // + // time ─────► + // ...──────────────┬───────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────... + // ▲ ▲ + // └─ Previous sample └─ This sample + // + // In this case, we'll push two samples: a) one for the current time, b ) an extra sample + // to represent the remaining cpu/wall time before the Waiting for GVL started: + // + // time ─────► + // ...──────────────┬───────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────... + // ▲ ▲ ▲ + // └─ Prev... └─ Extra sample └─ This sample + // + // 2. The current sample is the n-th one after we entered the Waiting for GVL state + // (wall_time_at_previous_sample_ns > abs(gvl_waiting_at)) + // + // time ─────► + // ...──────────────┬───────────────────────────────────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────────────────────────────────... + // ▲ ▲ ▲ + // └─ Previous sample └─ Previous sample └─ This sample + // + // --- + // + // Overall, gvl_waiting_at will be > 0 if still in the Waiting for GVL state and < 0 if we actually reached the end of + // the wait. + // + // It doesn't really matter if the thread is still waiting or just reached the end of the wait: each sample represents + // a snapshot at time ending now, so if the state finished, it just means the next sample will be a regular one. + + bool is_gvl_waiting_state = gvl_waiting_at != 0 && gvl_waiting_at != GVL_WAITING_ENABLED_EMPTY; + + if (is_gvl_waiting_state) { + if (gvl_waiting_at < 0) { + // Negative means the waiting for GVL just ended, so we clear the state, so next samples no longer represent waiting + rb_internal_thread_specific_set(thread_being_sampled, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + } + + long gvl_waiting_started_wall_time_ns = labs(gvl_waiting_at); + + if (thread_context->wall_time_at_previous_sample_ns < gvl_waiting_started_wall_time_ns) { // 1 above + long cpu_time_elapsed_ns = update_time_since_previous_sample( + &thread_context->cpu_time_at_previous_sample_ns, + current_cpu_time_ns, + thread_context->gc_tracking.cpu_time_at_start_ns, + IS_NOT_WALL_TIME + ); + + long duration_until_start_of_gvl_waiting_ns = update_time_since_previous_sample( + &thread_context->wall_time_at_previous_sample_ns, + gvl_waiting_started_wall_time_ns, + INVALID_TIME, + IS_WALL_TIME + ); + + // Push extra sample + trigger_sample_for_thread( + state, + thread_being_sampled, + stack_from_thread, + thread_context, + sampling_buffer, + (sample_values) {.cpu_time_ns = cpu_time_elapsed_ns, .cpu_or_wall_samples = 1, .wall_time_ns = duration_until_start_of_gvl_waiting_ns}, + gvl_waiting_started_wall_time_ns, + NULL, + NULL, + false // This is the extra sample before the wait begun; only the next sample will be in the gvl waiting state + ); + } + } + + // Don't assign/update cpu during Waiting for GVL + long cpu_time_elapsed_ns = is_gvl_waiting_state ? 0 : update_time_since_previous_sample( &thread_context->cpu_time_at_previous_sample_ns, current_cpu_time_ns, thread_context->gc_tracking.cpu_time_at_start_ns, IS_NOT_WALL_TIME ); - // TODO: This feels like a hack here -- is there a better place to do this? - intptr_t gvl_waiting_at = (intptr_t) rb_thread_local_variable_get(thread_being_sampled, per_thread_gvl_waiting_timestamp_key); - if (gvl_waiting_at != 0 && gvl_waiting_at != GVL_WAITING_ENABLED_EMPTY) { - // TODO: Was here - } - long wall_time_elapsed_ns = update_time_since_previous_sample( &thread_context->wall_time_at_previous_sample_ns, current_monotonic_wall_time_ns, @@ -554,6 +634,8 @@ void update_metrics_and_sample( IS_WALL_TIME ); + // TODO: Washere -- need to actually do something with the is_gvl_waiting_state + trigger_sample_for_thread( state, thread_being_sampled, @@ -563,7 +645,8 @@ void update_metrics_and_sample( (sample_values) {.cpu_time_ns = cpu_time_elapsed_ns, .cpu_or_wall_samples = 1, .wall_time_ns = wall_time_elapsed_ns}, current_monotonic_wall_time_ns, NULL, - NULL + NULL, + is_gvl_waiting_state ); } @@ -745,7 +828,8 @@ static void trigger_sample_for_thread( long current_monotonic_wall_time_ns, // These two labels are only used for allocation profiling; @ivoanjo: may want to refactor this at some point? ddog_CharSlice *ruby_vm_type, - ddog_CharSlice *class_name + ddog_CharSlice *class_name, + bool is_gvl_waiting_state ) { int max_label_count = 1 + // thread id @@ -864,7 +948,12 @@ static void trigger_sample_for_thread( sampling_buffer, state->recorder_instance, values, - (sample_labels) {.labels = slice_labels, .state_label = state_label, .end_timestamp_ns = end_timestamp_ns} + (sample_labels) { + .labels = slice_labels, + .state_label = state_label, + .end_timestamp_ns = end_timestamp_ns, + .is_gvl_waiting_state = is_gvl_waiting_state, + } ); } @@ -1368,7 +1457,8 @@ void thread_context_collector_sample_allocation(VALUE self_instance, unsigned in (sample_values) {.alloc_samples = sample_weight, .alloc_samples_unscaled = 1, .heap_sample = true}, INVALID_TIME, // For now we're not collecting timestamps for allocation events, as per profiling team internal discussions &ruby_vm_type, - optional_class_name + optional_class_name, + false ); } @@ -1560,7 +1650,7 @@ VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { if (!state->timeline_enabled) rb_raise(rb_eRuntimeError, "gvl profiling requires timeline to be enabled"); VALUE current_thread = rb_thread_current(); - struct per_thread_context *thread_context = get_or_create_context_for(thread, state); + struct per_thread_context *thread_context = get_or_create_context_for(current_thread, state); intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(current_thread, per_thread_gvl_waiting_timestamp_key); @@ -1571,18 +1661,18 @@ VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { return Qnil; } - // The timestamp is encoded as a negative value in thread_context_collector_on_gvl_running - long gvl_waiting_wall_time_ns = -gvl_waiting_at; + // We don't actually account for cpu-time during Waiting for GVL. BUT, we may chose to push an + // extra sample to represent the period prior to Waiting for GVL. To support that, we retrieve the current + // cpu-time of the thread and let `update_metrics_and_sample` decide what to do with it. - // Wrong update_metrics_and_sample( state, - /* thread_being_sampled: */ thread, - /* stack_from_thread: */ thread, + /* thread_being_sampled: */ current_thread, + /* stack_from_thread: */ current_thread, thread_context, thread_context->sampling_buffer, - FIXME, - FIXME + cpu_time_now_ns(thread_context), + monotonic_wall_time_now_ns(RAISE_ON_FAILURE) ); return Qnil; // To allow this to be called from rb_rescue2 diff --git a/ext/datadog_profiling_native_extension/stack_recorder.h b/ext/datadog_profiling_native_extension/stack_recorder.h index dbf104f33b0..dbbfe616b5e 100644 --- a/ext/datadog_profiling_native_extension/stack_recorder.h +++ b/ext/datadog_profiling_native_extension/stack_recorder.h @@ -21,6 +21,8 @@ typedef struct sample_labels { ddog_prof_Label *state_label; int64_t end_timestamp_ns; + + bool is_gvl_waiting_state; } sample_labels; void record_sample(VALUE recorder_instance, ddog_prof_Slice_Location locations, sample_values values, sample_labels labels); diff --git a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb index 02a7c7e8c69..827c8942b21 100644 --- a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb +++ b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb @@ -34,7 +34,7 @@ def initialize( ) end - gvl_profiling_enabled = true # TODO + gvl_profiling_enabled = ENV['TESTING_GVL_PROFILING'] == 'true' self.class._native_initialize( self, From 339e18d5859a6e25cc7bc9ab92d3315540918e2b Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 6 Sep 2024 09:24:04 +0100 Subject: [PATCH 07/42] Wire up `is_gvl_waiting_state` into a state_label --- .../collectors_stack.c | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_stack.c b/ext/datadog_profiling_native_extension/collectors_stack.c index b31ff671c51..711094ed657 100644 --- a/ext/datadog_profiling_native_extension/collectors_stack.c +++ b/ext/datadog_profiling_native_extension/collectors_stack.c @@ -251,13 +251,17 @@ void sample_thread( bool top_of_the_stack = i == 0; - // When there's only wall-time in a sample, this means that the thread was not active in the sampled period. - // - // We try to categorize what it was doing based on what we observe at the top of the stack. This is a very rough - // approximation, and in the future we hope to replace this with a more accurate approach (such as using the - // GVL instrumentation API.) if (top_of_the_stack && only_wall_time) { - if (!buffer->stack_buffer[i].is_ruby_frame) { + // When there's only wall-time in a sample, this means that the thread was not active in the sampled period. + // + // Did the caller already provide the state? + if (labels.is_gvl_waiting_state) { + state_label->str = DDOG_CHARSLICE_C("waiting for gvl"); + + // If not, we try to categorize what the thread was doing based on what we observe at the top of the stack. This is a very rough + // approximation, and in the future we hope to replace this with a more accurate approach (such as using the + // GVL instrumentation API.) + } else if (!buffer->stack_buffer[i].is_ruby_frame) { // We know that known versions of Ruby implement these using native code; thus if we find a method with the // same name that is not native code, we ignore it, as it's probably a user method that coincidentally // has the same name. Thus, even though "matching just by method name" is kinda weak, From a8f771bfa48394ec9044d9db2a31ccd3e1772a85 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 6 Sep 2024 09:37:56 +0100 Subject: [PATCH 08/42] Small cleanups from a self-review --- .../collectors_cpu_and_wall_time_worker.c | 12 +++++++----- .../collectors_thread_context.c | 12 +++++++----- 2 files changed, 14 insertions(+), 10 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index ab3cba8e788..5f6db965123 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -124,7 +124,7 @@ struct cpu_and_wall_time_worker_state { // Used to detect/avoid nested sampling, e.g. when on_newobj_event gets triggered by a memory allocation // that happens during another sample. bool during_sample; - // Only exists when sampling is active (gets created at started and cleaned on stop) + // Only exists when sampling is active (gets created at start and cleaned on stop) rb_internal_thread_event_hook_t *gvl_profiling_hook; struct stats { @@ -1286,13 +1286,15 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused) { // Be very careful about touching the `state` here or doing anything at all: // This function gets called even without the GVL, and even from background Ractors! - - VALUE current_thread = event_data->thread; + // + // In fact, the `target_thread` that this event is about may not even be the current thread. (So be careful with thread locals that + // are not directly tied to the `target_thread` object and the like) + VALUE target_thread = event_data->thread; if (event_id == RUBY_INTERNAL_THREAD_EVENT_READY) { /* waiting for gvl */ - thread_context_collector_on_gvl_waiting(current_thread); + thread_context_collector_on_gvl_waiting(target_thread); } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ - bool should_sample = thread_context_collector_on_gvl_running(current_thread); + bool should_sample = thread_context_collector_on_gvl_running(target_thread); if (should_sample) { // should_sample is only true if a thread belongs to the main Ractor, so we're good to go diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 51c492debd2..e0506e4354d 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -288,6 +288,7 @@ void collectors_thread_context_init(VALUE profiling_module) { at_parent_span_id_id = rb_intern_const("@parent_span_id"); at_datadog_trace_id = rb_intern_const("@datadog_trace"); + // This will raise if Ruby already ran out of thread-local keys per_thread_gvl_waiting_timestamp_key = rb_internal_thread_specific_key_create(); gc_profiling_init(); @@ -634,8 +635,6 @@ static void update_metrics_and_sample( IS_WALL_TIME ); - // TODO: Washere -- need to actually do something with the is_gvl_waiting_state - trigger_sample_for_thread( state, thread_being_sampled, @@ -1601,6 +1600,7 @@ void thread_context_collector_on_gvl_waiting(VALUE thread) { // per-thread context directly. // // Instead, we ask Ruby to hold the data we need in Ruby's own special per-thread context area + // that's thread-safe and built for this kind of use // // Also, this function can get called on the non-main Ractor. We deal with this by checking if the value in the context // is non-zero, since only `initialize_context` ever sets the value from 0 to non-zero for threads it sees. @@ -1636,7 +1636,7 @@ bool thread_context_collector_on_gvl_running(VALUE thread) { rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) gvl_waiting_at_is_now_running); } else { - // We decided not to sample. Let's mark the thread back to being profiled, but having no data yet. + // We decided not to sample. Let's mark the thread back to the initial enabled but empty state rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); } @@ -1656,7 +1656,8 @@ VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { if (gvl_waiting_at >= 0) { // @ivoanjo: I'm not sure if this can ever happen. This means that we're not on the same thread - // that ran `thread_context_collector_on_gvl_running` and made the decision to sample. + // that ran `thread_context_collector_on_gvl_running` and made the decision to sample OR a regular sample was + // triggered ahead of us. // We do nothing in this case. return Qnil; } @@ -1664,6 +1665,7 @@ VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { // We don't actually account for cpu-time during Waiting for GVL. BUT, we may chose to push an // extra sample to represent the period prior to Waiting for GVL. To support that, we retrieve the current // cpu-time of the thread and let `update_metrics_and_sample` decide what to do with it. + long cpu_time_for_thread = cpu_time_now_ns(thread_context); update_metrics_and_sample( state, @@ -1671,7 +1673,7 @@ VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { /* stack_from_thread: */ current_thread, thread_context, thread_context->sampling_buffer, - cpu_time_now_ns(thread_context), + cpu_time_for_thread, monotonic_wall_time_now_ns(RAISE_ON_FAILURE) ); From e655976a2976bc12457eee8f6131b0c1ecd8def0 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 09:37:33 +0100 Subject: [PATCH 09/42] Make GVL profiling not break older Rubies --- .../collectors_cpu_and_wall_time_worker.c | 107 +++--- .../collectors_thread_context.c | 334 +++++++++--------- .../extconf.rb | 4 + 3 files changed, 238 insertions(+), 207 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index 5f6db965123..b745b3ac1bc 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -124,8 +124,11 @@ struct cpu_and_wall_time_worker_state { // Used to detect/avoid nested sampling, e.g. when on_newobj_event gets triggered by a memory allocation // that happens during another sample. bool during_sample; - // Only exists when sampling is active (gets created at start and cleaned on stop) + + #ifndef NO_GVL_INSTRUMENTATION + // Only set when sampling is active (gets created at start and cleaned on stop) rb_internal_thread_event_hook_t *gvl_profiling_hook; + #endif struct stats { // # Generic stats @@ -232,7 +235,9 @@ static void delayed_error(struct cpu_and_wall_time_worker_state *state, const ch static VALUE _native_delayed_error(DDTRACE_UNUSED VALUE self, VALUE instance, VALUE error_msg); static VALUE _native_hold_signals(DDTRACE_UNUSED VALUE self); static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self); +#ifndef NO_GVL_INSTRUMENTATION static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused); +#endif static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused); // We're using `on_newobj_event` function with `rb_add_event_hook2`, which requires in its public signature a function @@ -370,7 +375,10 @@ static VALUE _native_new(VALUE klass) { state->stop_thread = Qnil; state->during_sample = false; - state->gvl_profiling_hook = NULL; + + #ifndef NO_GVL_INSTRUMENTATION + state->gvl_profiling_hook = NULL; + #endif reset_stats_not_thread_safe(state); discrete_dynamic_sampler_init(&state->allocation_sampler, "allocation", now); @@ -797,18 +805,21 @@ static VALUE release_gvl_and_run_sampling_trigger_loop(VALUE instance) { RUBY_EVENT_HOOK_FLAG_SAFE | RUBY_EVENT_HOOK_FLAG_RAW_ARG) ; } - if (state->gvl_profiling_enabled) { - state->gvl_profiling_hook = rb_internal_thread_add_event_hook( - on_gvl_event, - ( - // For now we're only asking for these events, even though there's more - // (e.g. check docs or gvl-tracing gem) - RUBY_INTERNAL_THREAD_EVENT_READY /* waiting for gvl */ | - RUBY_INTERNAL_THREAD_EVENT_RESUMED /* running/runnable */ - ), - NULL - ); - } + + #ifndef NO_GVL_INSTRUMENTATION + if (state->gvl_profiling_enabled) { + state->gvl_profiling_hook = rb_internal_thread_add_event_hook( + on_gvl_event, + ( + // For now we're only asking for these events, even though there's more + // (e.g. check docs or gvl-tracing gem) + RUBY_INTERNAL_THREAD_EVENT_READY /* waiting for gvl */ | + RUBY_INTERNAL_THREAD_EVENT_RESUMED /* running/runnable */ + ), + NULL + ); + } + #endif // Flag the profiler as running before we release the GVL, in case anyone's waiting to know about it rb_funcall(instance, rb_intern("signal_running"), 0); @@ -1204,10 +1215,12 @@ static void disable_tracepoints(struct cpu_and_wall_time_worker_state *state) { rb_remove_event_hook_with_data(on_newobj_event_as_hook, state->self_instance); - if (state->gvl_profiling_hook) { - rb_internal_thread_remove_event_hook(state->gvl_profiling_hook); - state->gvl_profiling_hook = NULL; - } + #ifndef NO_GVL_INSTRUMENTATION + if (state->gvl_profiling_hook) { + rb_internal_thread_remove_event_hook(state->gvl_profiling_hook); + state->gvl_profiling_hook = NULL; + } + #endif } static VALUE _native_with_blocked_sigprof(DDTRACE_UNUSED VALUE self) { @@ -1283,38 +1296,40 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { return Qtrue; } -static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused) { - // Be very careful about touching the `state` here or doing anything at all: - // This function gets called even without the GVL, and even from background Ractors! - // - // In fact, the `target_thread` that this event is about may not even be the current thread. (So be careful with thread locals that - // are not directly tied to the `target_thread` object and the like) - VALUE target_thread = event_data->thread; - - if (event_id == RUBY_INTERNAL_THREAD_EVENT_READY) { /* waiting for gvl */ - thread_context_collector_on_gvl_waiting(target_thread); - } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ - bool should_sample = thread_context_collector_on_gvl_running(target_thread); - - if (should_sample) { - // should_sample is only true if a thread belongs to the main Ractor, so we're good to go - rb_postponed_job_trigger(after_gvl_running_from_postponed_job_handle); +#ifndef NO_GVL_INSTRUMENTATION + static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused) { + // Be very careful about touching the `state` here or doing anything at all: + // This function gets called even without the GVL, and even from background Ractors! + // + // In fact, the `target_thread` that this event is about may not even be the current thread. (So be careful with thread locals that + // are not directly tied to the `target_thread` object and the like) + VALUE target_thread = event_data->thread; + + if (event_id == RUBY_INTERNAL_THREAD_EVENT_READY) { /* waiting for gvl */ + thread_context_collector_on_gvl_waiting(target_thread); + } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ + bool should_sample = thread_context_collector_on_gvl_running(target_thread); + + if (should_sample) { + // should_sample is only true if a thread belongs to the main Ractor, so we're good to go + rb_postponed_job_trigger(after_gvl_running_from_postponed_job_handle); + } + } else { + // This is a very delicate time and it's hard for us to raise an exception so let's at least complain to stderr + fprintf(stderr, "[ddtrace] Unexpected value in on_gvl_event (%d)\n", event_id); } - } else { - // This is a very delicate time and it's hard for us to raise an exception so let's at least complain to stderr - fprintf(stderr, "[ddtrace] Unexpected value in on_gvl_event (%d)\n", event_id); } -} -static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused) { - struct cpu_and_wall_time_worker_state *state = active_sampler_instance_state; // Read from global variable, see "sampler global state safety" note above + static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused) { + struct cpu_and_wall_time_worker_state *state = active_sampler_instance_state; // Read from global variable, see "sampler global state safety" note above - // This can potentially happen if the CpuAndWallTimeWorker was stopped while the postponed job was waiting to be executed; nothing to do - if (state == NULL) return; + // This can potentially happen if the CpuAndWallTimeWorker was stopped while the postponed job was waiting to be executed; nothing to do + if (state == NULL) return; - state->during_sample = true; + state->during_sample = true; - safely_call(thread_context_collector_sample_after_gvl_running, state->thread_context_collector_instance, state->self_instance); + safely_call(thread_context_collector_sample_after_gvl_running, state->thread_context_collector_instance, state->self_instance); - state->during_sample = false; -} + state->during_sample = false; + } +#endif diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index e0506e4354d..ea9bcb5cbad 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -92,7 +92,9 @@ static ID at_otel_values_id; // id of :@otel_values in Ruby static ID at_parent_span_id_id; // id of :@parent_span_id in Ruby static ID at_datadog_trace_id; // id of :@datadog_trace in Ruby +#ifndef NO_GVL_INSTRUMENTATION static rb_internal_thread_specific_key_t per_thread_gvl_waiting_timestamp_key; +#endif // Contains state for a single ThreadContext instance struct thread_context_collector_state { @@ -288,8 +290,10 @@ void collectors_thread_context_init(VALUE profiling_module) { at_parent_span_id_id = rb_intern_const("@parent_span_id"); at_datadog_trace_id = rb_intern_const("@datadog_trace"); - // This will raise if Ruby already ran out of thread-local keys - per_thread_gvl_waiting_timestamp_key = rb_internal_thread_specific_key_create(); + #ifndef NO_GVL_INSTRUMENTATION + // This will raise if Ruby already ran out of thread-local keys + per_thread_gvl_waiting_timestamp_key = rb_internal_thread_specific_key_create(); + #endif gc_profiling_init(); } @@ -532,89 +536,93 @@ static void update_metrics_and_sample( long current_cpu_time_ns, long current_monotonic_wall_time_ns ) { - // TODO: This feels like a hack here -- is there a better place to do this? - intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread_being_sampled, per_thread_gvl_waiting_timestamp_key); - - // We can be in one of 2 situations here: - // - // 1. The current sample is the first one after we entered the Waiting for GVL state - // (wall_time_at_previous_sample_ns < abs(gvl_waiting_at)) - // - // time ─────► - // ...──────────────┬───────────────────... - // Other state │ Waiting for GVL - // ...──────────────┴───────────────────... - // ▲ ▲ - // └─ Previous sample └─ This sample - // - // In this case, we'll push two samples: a) one for the current time, b ) an extra sample - // to represent the remaining cpu/wall time before the Waiting for GVL started: - // - // time ─────► - // ...──────────────┬───────────────────... - // Other state │ Waiting for GVL - // ...──────────────┴───────────────────... - // ▲ ▲ ▲ - // └─ Prev... └─ Extra sample └─ This sample - // - // 2. The current sample is the n-th one after we entered the Waiting for GVL state - // (wall_time_at_previous_sample_ns > abs(gvl_waiting_at)) - // - // time ─────► - // ...──────────────┬───────────────────────────────────────────────... - // Other state │ Waiting for GVL - // ...──────────────┴───────────────────────────────────────────────... - // ▲ ▲ ▲ - // └─ Previous sample └─ Previous sample └─ This sample - // - // --- - // - // Overall, gvl_waiting_at will be > 0 if still in the Waiting for GVL state and < 0 if we actually reached the end of - // the wait. - // - // It doesn't really matter if the thread is still waiting or just reached the end of the wait: each sample represents - // a snapshot at time ending now, so if the state finished, it just means the next sample will be a regular one. - - bool is_gvl_waiting_state = gvl_waiting_at != 0 && gvl_waiting_at != GVL_WAITING_ENABLED_EMPTY; - - if (is_gvl_waiting_state) { - if (gvl_waiting_at < 0) { - // Negative means the waiting for GVL just ended, so we clear the state, so next samples no longer represent waiting - rb_internal_thread_specific_set(thread_being_sampled, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); - } - - long gvl_waiting_started_wall_time_ns = labs(gvl_waiting_at); - - if (thread_context->wall_time_at_previous_sample_ns < gvl_waiting_started_wall_time_ns) { // 1 above - long cpu_time_elapsed_ns = update_time_since_previous_sample( - &thread_context->cpu_time_at_previous_sample_ns, - current_cpu_time_ns, - thread_context->gc_tracking.cpu_time_at_start_ns, - IS_NOT_WALL_TIME - ); - - long duration_until_start_of_gvl_waiting_ns = update_time_since_previous_sample( - &thread_context->wall_time_at_previous_sample_ns, - gvl_waiting_started_wall_time_ns, - INVALID_TIME, - IS_WALL_TIME - ); + #ifndef NO_GVL_INSTRUMENTATION + // TODO: This feels like a hack here -- is there a better place to do this? + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread_being_sampled, per_thread_gvl_waiting_timestamp_key); + + // We can be in one of 2 situations here: + // + // 1. The current sample is the first one after we entered the Waiting for GVL state + // (wall_time_at_previous_sample_ns < abs(gvl_waiting_at)) + // + // time ─────► + // ...──────────────┬───────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────... + // ▲ ▲ + // └─ Previous sample └─ This sample + // + // In this case, we'll push two samples: a) one for the current time, b ) an extra sample + // to represent the remaining cpu/wall time before the Waiting for GVL started: + // + // time ─────► + // ...──────────────┬───────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────... + // ▲ ▲ ▲ + // └─ Prev... └─ Extra sample └─ This sample + // + // 2. The current sample is the n-th one after we entered the Waiting for GVL state + // (wall_time_at_previous_sample_ns > abs(gvl_waiting_at)) + // + // time ─────► + // ...──────────────┬───────────────────────────────────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────────────────────────────────... + // ▲ ▲ ▲ + // └─ Previous sample └─ Previous sample └─ This sample + // + // --- + // + // Overall, gvl_waiting_at will be > 0 if still in the Waiting for GVL state and < 0 if we actually reached the end of + // the wait. + // + // It doesn't really matter if the thread is still waiting or just reached the end of the wait: each sample represents + // a snapshot at time ending now, so if the state finished, it just means the next sample will be a regular one. + + bool is_gvl_waiting_state = gvl_waiting_at != 0 && gvl_waiting_at != GVL_WAITING_ENABLED_EMPTY; + + if (is_gvl_waiting_state) { + if (gvl_waiting_at < 0) { + // Negative means the waiting for GVL just ended, so we clear the state, so next samples no longer represent waiting + rb_internal_thread_specific_set(thread_being_sampled, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + } - // Push extra sample - trigger_sample_for_thread( - state, - thread_being_sampled, - stack_from_thread, - thread_context, - sampling_buffer, - (sample_values) {.cpu_time_ns = cpu_time_elapsed_ns, .cpu_or_wall_samples = 1, .wall_time_ns = duration_until_start_of_gvl_waiting_ns}, - gvl_waiting_started_wall_time_ns, - NULL, - NULL, - false // This is the extra sample before the wait begun; only the next sample will be in the gvl waiting state - ); + long gvl_waiting_started_wall_time_ns = labs(gvl_waiting_at); + + if (thread_context->wall_time_at_previous_sample_ns < gvl_waiting_started_wall_time_ns) { // 1 above + long cpu_time_elapsed_ns = update_time_since_previous_sample( + &thread_context->cpu_time_at_previous_sample_ns, + current_cpu_time_ns, + thread_context->gc_tracking.cpu_time_at_start_ns, + IS_NOT_WALL_TIME + ); + + long duration_until_start_of_gvl_waiting_ns = update_time_since_previous_sample( + &thread_context->wall_time_at_previous_sample_ns, + gvl_waiting_started_wall_time_ns, + INVALID_TIME, + IS_WALL_TIME + ); + + // Push extra sample + trigger_sample_for_thread( + state, + thread_being_sampled, + stack_from_thread, + thread_context, + sampling_buffer, + (sample_values) {.cpu_time_ns = cpu_time_elapsed_ns, .cpu_or_wall_samples = 1, .wall_time_ns = duration_until_start_of_gvl_waiting_ns}, + gvl_waiting_started_wall_time_ns, + NULL, + NULL, + false // This is the extra sample before the wait begun; only the next sample will be in the gvl waiting state + ); + } } - } + #else + bool is_gvl_waiting_state = false; + #endif // Don't assign/update cpu during Waiting for GVL long cpu_time_elapsed_ns = is_gvl_waiting_state ? 0 : update_time_since_previous_sample( @@ -1053,17 +1061,19 @@ static void initialize_context(VALUE thread, struct per_thread_context *thread_c thread_context->gc_tracking.cpu_time_at_start_ns = INVALID_TIME; thread_context->gc_tracking.wall_time_at_start_ns = INVALID_TIME; - // We use this special location to store data that can be accessed without any - // kind of synchronization (e.g. by threads without the GVL). - // - // We set this marker here for two purposes: - // * To make sure there's no stale data from a previous execution of the profiler. - // * To mark threads that are actually being profiled - // - // (Setting this is potentially a race, but what we want is to avoid _stale_ data, so - // if this gets set concurrently with context initialization, then such a value will belong - // to the current profiler instance, so that's OK) - rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + #ifndef NO_GVL_INSTRUMENTATION + // We use this special location to store data that can be accessed without any + // kind of synchronization (e.g. by threads without the GVL). + // + // We set this marker here for two purposes: + // * To make sure there's no stale data from a previous execution of the profiler. + // * To mark threads that are actually being profiled + // + // (Setting this is potentially a race, but what we want is to avoid _stale_ data, so + // if this gets set concurrently with context initialization, then such a value will belong + // to the current profiler instance, so that's OK) + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + #endif } static void free_context(struct per_thread_context* thread_context) { @@ -1594,88 +1604,90 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return Qtrue; } -// This function can get called from outside the GVL and even on non-main Ractors -void thread_context_collector_on_gvl_waiting(VALUE thread) { - // Because this function gets called from a thread that is NOT holding the GVL, we avoid touching the - // per-thread context directly. - // - // Instead, we ask Ruby to hold the data we need in Ruby's own special per-thread context area - // that's thread-safe and built for this kind of use - // - // Also, this function can get called on the non-main Ractor. We deal with this by checking if the value in the context - // is non-zero, since only `initialize_context` ever sets the value from 0 to non-zero for threads it sees. - intptr_t thread_being_profiled = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); - if (!thread_being_profiled) return; - - long current_monotonic_wall_time_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE); - if (current_monotonic_wall_time_ns <= 0 || current_monotonic_wall_time_ns > GVL_WAITING_ENABLED_EMPTY) return; +#ifndef NO_GVL_INSTRUMENTATION + // This function can get called from outside the GVL and even on non-main Ractors + void thread_context_collector_on_gvl_waiting(VALUE thread) { + // Because this function gets called from a thread that is NOT holding the GVL, we avoid touching the + // per-thread context directly. + // + // Instead, we ask Ruby to hold the data we need in Ruby's own special per-thread context area + // that's thread-safe and built for this kind of use + // + // Also, this function can get called on the non-main Ractor. We deal with this by checking if the value in the context + // is non-zero, since only `initialize_context` ever sets the value from 0 to non-zero for threads it sees. + intptr_t thread_being_profiled = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); + if (!thread_being_profiled) return; + + long current_monotonic_wall_time_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE); + if (current_monotonic_wall_time_ns <= 0 || current_monotonic_wall_time_ns > GVL_WAITING_ENABLED_EMPTY) return; + + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) current_monotonic_wall_time_ns); + } - rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) current_monotonic_wall_time_ns); -} + #define WAITING_FOR_GVL_THRESHOLD_NS MILLIS_AS_NS(10) -#define WAITING_FOR_GVL_THRESHOLD_NS MILLIS_AS_NS(10) + // This function can get called from outside the GVL and even on non-main Ractors + __attribute__((warn_unused_result)) + bool thread_context_collector_on_gvl_running(VALUE thread) { + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); -// This function can get called from outside the GVL and even on non-main Ractors -__attribute__((warn_unused_result)) -bool thread_context_collector_on_gvl_running(VALUE thread) { - intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); + // Thread was not being profiled / not waiting on gvl + if (gvl_waiting_at == 0 || gvl_waiting_at == GVL_WAITING_ENABLED_EMPTY) return false; - // Thread was not being profiled / not waiting on gvl - if (gvl_waiting_at == 0 || gvl_waiting_at == GVL_WAITING_ENABLED_EMPTY) return false; + // @ivoanjo: I'm not sure if this can happen -- It means we should've sampled already but didn't + if (gvl_waiting_at < 0) return true; - // @ivoanjo: I'm not sure if this can happen -- It means we should've sampled already but didn't - if (gvl_waiting_at < 0) return true; + long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - gvl_waiting_at; - long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - gvl_waiting_at; + bool should_sample = waiting_for_gvl_duration_ns >= WAITING_FOR_GVL_THRESHOLD_NS; - bool should_sample = waiting_for_gvl_duration_ns >= WAITING_FOR_GVL_THRESHOLD_NS; + if (should_sample) { + // We flip the gvl_waiting_at to negative to mark that the thread is now running + intptr_t gvl_waiting_at_is_now_running = -gvl_waiting_at; - if (should_sample) { - // We flip the gvl_waiting_at to negative to mark that the thread is now running - intptr_t gvl_waiting_at_is_now_running = -gvl_waiting_at; + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) gvl_waiting_at_is_now_running); + } else { + // We decided not to sample. Let's mark the thread back to the initial enabled but empty state + rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + } - rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) gvl_waiting_at_is_now_running); - } else { - // We decided not to sample. Let's mark the thread back to the initial enabled but empty state - rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + return should_sample; } - return should_sample; -} + VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { + struct thread_context_collector_state *state; + TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); -VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { - struct thread_context_collector_state *state; - TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); - - if (!state->timeline_enabled) rb_raise(rb_eRuntimeError, "gvl profiling requires timeline to be enabled"); + if (!state->timeline_enabled) rb_raise(rb_eRuntimeError, "gvl profiling requires timeline to be enabled"); - VALUE current_thread = rb_thread_current(); - struct per_thread_context *thread_context = get_or_create_context_for(current_thread, state); + VALUE current_thread = rb_thread_current(); + struct per_thread_context *thread_context = get_or_create_context_for(current_thread, state); - intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(current_thread, per_thread_gvl_waiting_timestamp_key); + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(current_thread, per_thread_gvl_waiting_timestamp_key); - if (gvl_waiting_at >= 0) { - // @ivoanjo: I'm not sure if this can ever happen. This means that we're not on the same thread - // that ran `thread_context_collector_on_gvl_running` and made the decision to sample OR a regular sample was - // triggered ahead of us. - // We do nothing in this case. - return Qnil; - } + if (gvl_waiting_at >= 0) { + // @ivoanjo: I'm not sure if this can ever happen. This means that we're not on the same thread + // that ran `thread_context_collector_on_gvl_running` and made the decision to sample OR a regular sample was + // triggered ahead of us. + // We do nothing in this case. + return Qnil; + } - // We don't actually account for cpu-time during Waiting for GVL. BUT, we may chose to push an - // extra sample to represent the period prior to Waiting for GVL. To support that, we retrieve the current - // cpu-time of the thread and let `update_metrics_and_sample` decide what to do with it. - long cpu_time_for_thread = cpu_time_now_ns(thread_context); + // We don't actually account for cpu-time during Waiting for GVL. BUT, we may chose to push an + // extra sample to represent the period prior to Waiting for GVL. To support that, we retrieve the current + // cpu-time of the thread and let `update_metrics_and_sample` decide what to do with it. + long cpu_time_for_thread = cpu_time_now_ns(thread_context); - update_metrics_and_sample( - state, - /* thread_being_sampled: */ current_thread, - /* stack_from_thread: */ current_thread, - thread_context, - thread_context->sampling_buffer, - cpu_time_for_thread, - monotonic_wall_time_now_ns(RAISE_ON_FAILURE) - ); + update_metrics_and_sample( + state, + /* thread_being_sampled: */ current_thread, + /* stack_from_thread: */ current_thread, + thread_context, + thread_context->sampling_buffer, + cpu_time_for_thread, + monotonic_wall_time_now_ns(RAISE_ON_FAILURE) + ); - return Qnil; // To allow this to be called from rb_rescue2 -} + return Qnil; // To allow this to be called from rb_rescue2 + } +#endif diff --git a/ext/datadog_profiling_native_extension/extconf.rb b/ext/datadog_profiling_native_extension/extconf.rb index e71c28e32f8..21b1b3dccb0 100644 --- a/ext/datadog_profiling_native_extension/extconf.rb +++ b/ext/datadog_profiling_native_extension/extconf.rb @@ -131,6 +131,10 @@ def skip_building_extension!(reason) have_func "malloc_stats" +# On older Rubies, there was no GVL instrumentation API and APIs created to support it +# TODO: We can probably support Ruby 3.2 as well here, but not for the first version +$defs << "-DNO_GVL_INSTRUMENTATION" if RUBY_VERSION < "3.3" + # On older Rubies, rb_postponed_job_preregister/rb_postponed_job_trigger did not exist $defs << "-DNO_POSTPONED_TRIGGER" if RUBY_VERSION < "3.3" From 3d6e2384d0ebf669522832f0dfae21ae5fda019d Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 10:51:13 +0100 Subject: [PATCH 10/42] Fix crash when no options are provided --- ext/libdatadog_api/crashtracker.c | 1 + 1 file changed, 1 insertion(+) diff --git a/ext/libdatadog_api/crashtracker.c b/ext/libdatadog_api/crashtracker.c index 8e631ac8ff7..82c1efc1a84 100644 --- a/ext/libdatadog_api/crashtracker.c +++ b/ext/libdatadog_api/crashtracker.c @@ -28,6 +28,7 @@ void crashtracker_init(VALUE crashtracking_module) { static VALUE _native_start_or_update_on_fork(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self) { VALUE options; rb_scan_args(argc, argv, "0:", &options); + if (options == Qnil) options = rb_hash_new(); VALUE agent_base_url = rb_hash_fetch(options, ID2SYM(rb_intern("agent_base_url"))); VALUE path_to_crashtracking_receiver_binary = rb_hash_fetch(options, ID2SYM(rb_intern("path_to_crashtracking_receiver_binary"))); From 83e38c6c29782b627e2e92be256ea9d98f411d37 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 10:52:21 +0100 Subject: [PATCH 11/42] Add default arguments handling to _native_sample This test helper method was getting very annoying to maintain every time we needed to test new features. --- .../profiler_memory_sample_serialize.rb | 2 - .../collectors_stack.c | 40 +++++++++---------- .../profiling/collectors/stack_spec.rb | 4 +- spec/datadog/profiling/stack_recorder_spec.rb | 18 ++++----- 4 files changed, 29 insertions(+), 35 deletions(-) diff --git a/benchmarks/profiler_memory_sample_serialize.rb b/benchmarks/profiler_memory_sample_serialize.rb index 3f2ebd42513..56c4ed62e60 100644 --- a/benchmarks/profiler_memory_sample_serialize.rb +++ b/benchmarks/profiler_memory_sample_serialize.rb @@ -30,8 +30,6 @@ def sample_object(recorder, depth = 0) METRIC_VALUES, [], [], - 400, - false ) obj else diff --git a/ext/datadog_profiling_native_extension/collectors_stack.c b/ext/datadog_profiling_native_extension/collectors_stack.c index 711094ed657..f00b5080690 100644 --- a/ext/datadog_profiling_native_extension/collectors_stack.c +++ b/ext/datadog_profiling_native_extension/collectors_stack.c @@ -20,16 +20,7 @@ struct sampling_buffer { frame_info *stack_buffer; }; // Note: typedef'd in the header to sampling_buffer -static VALUE _native_sample( - VALUE self, - VALUE thread, - VALUE recorder_instance, - VALUE metric_values_hash, - VALUE labels_array, - VALUE numeric_labels_array, - VALUE max_frames, - VALUE in_gc -); +static VALUE _native_sample(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self); static VALUE native_sample_do(VALUE args); static VALUE native_sample_ensure(VALUE args); static void maybe_add_placeholder_frames_omitted(VALUE thread, sampling_buffer* buffer, char *frames_omitted_message, int frames_omitted_message_size); @@ -47,7 +38,7 @@ void collectors_stack_init(VALUE profiling_module) { // Hosts methods used for testing the native code using RSpec VALUE testing_module = rb_define_module_under(collectors_stack_class, "Testing"); - rb_define_singleton_method(testing_module, "_native_sample", _native_sample, 7); + rb_define_singleton_method(testing_module, "_native_sample", _native_sample, -1); missing_string = rb_str_new2(""); rb_global_variable(&missing_string); @@ -65,16 +56,23 @@ struct native_sample_args { // This method exists only to enable testing Datadog::Profiling::Collectors::Stack behavior using RSpec. // It SHOULD NOT be used for other purposes. -static VALUE _native_sample( - DDTRACE_UNUSED VALUE _self, - VALUE thread, - VALUE recorder_instance, - VALUE metric_values_hash, - VALUE labels_array, - VALUE numeric_labels_array, - VALUE max_frames, - VALUE in_gc -) { +static VALUE _native_sample(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self) { + // Positional args + VALUE thread; + VALUE recorder_instance; + VALUE metric_values_hash; + VALUE labels_array; + VALUE numeric_labels_array; + VALUE options; + + rb_scan_args(argc, argv, "5:", &thread, &recorder_instance, &metric_values_hash, &labels_array, &numeric_labels_array, &options); + + if (options == Qnil) options = rb_hash_new(); + + // Optional keyword args + VALUE max_frames = rb_hash_lookup2(options, ID2SYM(rb_intern("max_frames")), INT2NUM(400)); + VALUE in_gc = rb_hash_lookup2(options, ID2SYM(rb_intern("in_gc")), Qfalse); + ENFORCE_TYPE(metric_values_hash, T_HASH); ENFORCE_TYPE(labels_array, T_ARRAY); ENFORCE_TYPE(numeric_labels_array, T_ARRAY); diff --git a/spec/datadog/profiling/collectors/stack_spec.rb b/spec/datadog/profiling/collectors/stack_spec.rb index 03da15324d1..5658d578502 100644 --- a/spec/datadog/profiling/collectors/stack_spec.rb +++ b/spec/datadog/profiling/collectors/stack_spec.rb @@ -17,9 +17,9 @@ let(:reference_stack) { convert_reference_stack(raw_reference_stack) } let(:gathered_stack) { stacks.fetch(:gathered) } - def sample(thread, recorder_instance, metric_values_hash, labels_array, max_frames: 400, in_gc: false) + def sample(thread, recorder_instance, metric_values_hash, labels_array, **options) numeric_labels_array = [] - described_class::Testing._native_sample(thread, recorder_instance, metric_values_hash, labels_array, numeric_labels_array, max_frames, in_gc) + described_class::Testing._native_sample(thread, recorder_instance, metric_values_hash, labels_array, numeric_labels_array, **options) end # This spec explicitly tests the main thread because an unpatched rb_profile_frames returns one more frame in the diff --git a/spec/datadog/profiling/stack_recorder_spec.rb b/spec/datadog/profiling/stack_recorder_spec.rb index 07b87203461..f612352b4c0 100644 --- a/spec/datadog/profiling/stack_recorder_spec.rb +++ b/spec/datadog/profiling/stack_recorder_spec.rb @@ -262,7 +262,7 @@ def sample_types_from(decoded_profile) before do Datadog::Profiling::Collectors::Stack::Testing - ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels, 400, false) + ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels) expect(samples.size).to be 1 end @@ -337,8 +337,6 @@ def sample_types_from(decoded_profile) metric_values, {"local root span id" => "incorrect", "state" => "unknown"}.to_a, [], - 400, - false, ) end.to raise_error(ArgumentError) end @@ -355,7 +353,7 @@ def sample_types_from(decoded_profile) sample = proc do |numeric_labels = {}| Datadog::Profiling::Collectors::Stack::Testing._native_sample( - Thread.current, stack_recorder, metric_values, {"state" => "unknown"}.to_a, numeric_labels.to_a, 400, false + Thread.current, stack_recorder, metric_values, {"state" => "unknown"}.to_a, numeric_labels.to_a ) end @@ -415,7 +413,7 @@ def sample_allocation(obj) # Heap sampling currently requires this 2-step process to first pass data about the allocated object... described_class::Testing._native_track_object(stack_recorder, obj, sample_rate, obj.class.name) Datadog::Profiling::Collectors::Stack::Testing - ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels, 400, false) + ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels) end before do @@ -794,7 +792,7 @@ def create_obj_in_recycled_slot(should_sample_original: false) it "propagates the exception" do expect do Datadog::Profiling::Collectors::Stack::Testing - ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels, 400, false) + ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels) end.to raise_error(RuntimeError, /Ended a heap recording/) end @@ -805,7 +803,7 @@ def create_obj_in_recycled_slot(should_sample_original: false) begin Datadog::Profiling::Collectors::Stack::Testing - ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels, 400, false) + ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels) rescue # rubocop:disable Lint/SuppressedException end @@ -925,7 +923,7 @@ def create_obj_in_recycled_slot(should_sample_original: false) it "makes the next calls to serialize return no data" do # Add some data Datadog::Profiling::Collectors::Stack::Testing - ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels, 400, false) + ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels) # Sanity check: validate that data is there, to avoid the test passing because of other issues sanity_check_samples = samples_from_pprof(stack_recorder.serialize[2]) @@ -933,7 +931,7 @@ def create_obj_in_recycled_slot(should_sample_original: false) # Add some data, again Datadog::Profiling::Collectors::Stack::Testing - ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels, 400, false) + ._native_sample(Thread.current, stack_recorder, metric_values, labels, numeric_labels) reset_after_fork @@ -1011,7 +1009,7 @@ def sample_allocation(obj) # Heap sampling currently requires this 2-step process to first pass data about the allocated object... described_class::Testing._native_track_object(stack_recorder, obj, 1, obj.class.name) Datadog::Profiling::Collectors::Stack::Testing._native_sample( - Thread.current, stack_recorder, {"alloc-samples" => 1, "heap_sample" => true}, [], [], 400, false + Thread.current, stack_recorder, {"alloc-samples" => 1, "heap_sample" => true}, [], [], ) end From 135b555d003671a93fdb646d42d52c234b52ee19 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 10:53:11 +0100 Subject: [PATCH 12/42] Switch from hash to array to hopefully avoid flakiness The flakiness on this spec showed up again when I slightly refactored the `Collectors::Stack::Testing._native_sample` method but goes away if we use an array. I really dislike all the handwaving around this, but I'm not sure what we can do better in this case. --- spec/datadog/profiling/stack_recorder_spec.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/datadog/profiling/stack_recorder_spec.rb b/spec/datadog/profiling/stack_recorder_spec.rb index f612352b4c0..a9d65c1495b 100644 --- a/spec/datadog/profiling/stack_recorder_spec.rb +++ b/spec/datadog/profiling/stack_recorder_spec.rb @@ -1026,7 +1026,7 @@ def sample_allocation(obj) # See also the discussion on commit 2fc03d5ae5860d4e9a75ce3825fba95ed288a1 for an earlier attempt at fixing this. dead_heap_samples = 10 dead_heap_samples.times do |_i| - obj = {} + obj = [] sample_allocation(obj) end From bf4d86d237c21b8eb59e1bf3ae7a3c881800de8b Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 11:17:18 +0100 Subject: [PATCH 13/42] Add testing for new `is_gvl_waiting_state` flag --- .../collectors_stack.c | 13 ++++--- .../stack_recorder.h | 3 +- .../collectors/cpu_and_wall_time_worker.rb | 2 +- .../profiling/collectors/stack_spec.rb | 35 +++++++++++++++++-- 4 files changed, 43 insertions(+), 10 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_stack.c b/ext/datadog_profiling_native_extension/collectors_stack.c index f00b5080690..1ba7af001cf 100644 --- a/ext/datadog_profiling_native_extension/collectors_stack.c +++ b/ext/datadog_profiling_native_extension/collectors_stack.c @@ -72,6 +72,7 @@ static VALUE _native_sample(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self) { // Optional keyword args VALUE max_frames = rb_hash_lookup2(options, ID2SYM(rb_intern("max_frames")), INT2NUM(400)); VALUE in_gc = rb_hash_lookup2(options, ID2SYM(rb_intern("in_gc")), Qfalse); + VALUE is_gvl_waiting_state = rb_hash_lookup2(options, ID2SYM(rb_intern("is_gvl_waiting_state")), Qfalse); ENFORCE_TYPE(metric_values_hash, T_HASH); ENFORCE_TYPE(labels_array, T_ARRAY); @@ -126,7 +127,7 @@ static VALUE _native_sample(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self) { .in_gc = in_gc, .recorder_instance = recorder_instance, .values = values, - .labels = (sample_labels) {.labels = slice_labels, .state_label = state_label}, + .labels = (sample_labels) {.labels = slice_labels, .state_label = state_label, .is_gvl_waiting_state = is_gvl_waiting_state == Qtrue}, .thread = thread, .locations = locations, .buffer = buffer, @@ -220,7 +221,10 @@ void sample_thread( if (cpu_or_wall_sample && state_label == NULL) rb_raise(rb_eRuntimeError, "BUG: Unexpected missing state_label"); - if (has_cpu_time) state_label->str = DDOG_CHARSLICE_C("had cpu"); + if (has_cpu_time) { + state_label->str = DDOG_CHARSLICE_C("had cpu"); + if (labels.is_gvl_waiting_state) rb_raise(rb_eRuntimeError, "BUG: Unexpected combination of cpu-time with is_gvl_waiting"); + } for (int i = captured_frames - 1; i >= 0; i--) { VALUE name, filename; @@ -249,14 +253,13 @@ void sample_thread( bool top_of_the_stack = i == 0; + // When there's only wall-time in a sample, this means that the thread was not active in the sampled period. if (top_of_the_stack && only_wall_time) { - // When there's only wall-time in a sample, this means that the thread was not active in the sampled period. - // // Did the caller already provide the state? if (labels.is_gvl_waiting_state) { state_label->str = DDOG_CHARSLICE_C("waiting for gvl"); - // If not, we try to categorize what the thread was doing based on what we observe at the top of the stack. This is a very rough + // Otherwise, we try to categorize what the thread was doing based on what we observe at the top of the stack. This is a very rough // approximation, and in the future we hope to replace this with a more accurate approach (such as using the // GVL instrumentation API.) } else if (!buffer->stack_buffer[i].is_ruby_frame) { diff --git a/ext/datadog_profiling_native_extension/stack_recorder.h b/ext/datadog_profiling_native_extension/stack_recorder.h index dbbfe616b5e..dc6c7847458 100644 --- a/ext/datadog_profiling_native_extension/stack_recorder.h +++ b/ext/datadog_profiling_native_extension/stack_recorder.h @@ -19,10 +19,9 @@ typedef struct sample_labels { // 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. ddog_prof_Label *state_label; + bool is_gvl_waiting_state; int64_t end_timestamp_ns; - - bool is_gvl_waiting_state; } sample_labels; void record_sample(VALUE recorder_instance, ddog_prof_Slice_Location locations, sample_values values, sample_labels labels); diff --git a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb index 827c8942b21..abaa2bbea70 100644 --- a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb +++ b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb @@ -34,7 +34,7 @@ def initialize( ) end - gvl_profiling_enabled = ENV['TESTING_GVL_PROFILING'] == 'true' + gvl_profiling_enabled = ENV["TESTING_GVL_PROFILING"] == "true" self.class._native_initialize( self, diff --git a/spec/datadog/profiling/collectors/stack_spec.rb b/spec/datadog/profiling/collectors/stack_spec.rb index 5658d578502..47ab3ea53f3 100644 --- a/spec/datadog/profiling/collectors/stack_spec.rb +++ b/spec/datadog/profiling/collectors/stack_spec.rb @@ -214,6 +214,37 @@ def call_sleep end end + context "when sampling a thread in gvl waiting state" do + let(:do_in_background_thread) do + proc do |ready_queue| + ready_queue << true + sleep + end + end + + context "when the thread has cpu time" do + let(:metric_values) { {"cpu-time" => 123, "cpu-samples" => 456, "wall-time" => 789} } + + it do + expect { + sample_and_decode(background_thread, :labels, is_gvl_waiting_state: true) + }.to raise_error(RuntimeError, /BUG: .* is_gvl_waiting/) + end + end + + context "when the thread has wall time but no cpu time" do + let(:metric_values) { {"cpu-time" => 0, "cpu-samples" => 456, "wall-time" => 789} } + + it do + expect(sample_and_decode(background_thread, :labels, is_gvl_waiting_state: true)).to include(state: "waiting for gvl") + end + + it "takes precedence over approximate state categorization" do + expect(sample_and_decode(background_thread, :labels, is_gvl_waiting_state: false)).to include(state: "sleeping") + end + end + end + describe "approximate thread state categorization based on current stack" do before do wait_for { background_thread.backtrace_locations.first.base_label }.to eq(expected_method_name) @@ -672,8 +703,8 @@ def convert_reference_stack(raw_reference_stack) end end - def sample_and_decode(thread, data = :locations, max_frames: 400, recorder: build_stack_recorder, in_gc: false) - sample(thread, recorder, metric_values, labels, max_frames: max_frames, in_gc: in_gc) + def sample_and_decode(thread, data = :locations, recorder: build_stack_recorder, **options) + sample(thread, recorder, metric_values, labels, **options) samples = samples_from_pprof(recorder.serialize!) From 3db9e5fed813585002d71a2eb4bc5787c82774b8 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 15:42:17 +0100 Subject: [PATCH 14/42] Refactor "Waiting for GVL" logic away from `update_metrics_and_sample` --- .../collectors_thread_context.c | 209 ++++++++++-------- 1 file changed, 120 insertions(+), 89 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index ea9bcb5cbad..c6c8833f7df 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -248,6 +248,14 @@ static void ddtrace_otel_trace_identifiers_for( VALUE otel_values ); static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE skipped_samples); +static bool handle_gvl_waiting( + struct thread_context_collector_state *state, + VALUE thread_being_sampled, + VALUE stack_from_thread, + struct per_thread_context *thread_context, + sampling_buffer* sampling_buffer, + long current_cpu_time_ns +); void collectors_thread_context_init(VALUE profiling_module) { VALUE collectors_module = rb_define_module_under(profiling_module, "Collectors"); @@ -536,95 +544,10 @@ static void update_metrics_and_sample( long current_cpu_time_ns, long current_monotonic_wall_time_ns ) { - #ifndef NO_GVL_INSTRUMENTATION - // TODO: This feels like a hack here -- is there a better place to do this? - intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread_being_sampled, per_thread_gvl_waiting_timestamp_key); + bool is_gvl_waiting_state = + handle_gvl_waiting(state, thread_being_sampled, stack_from_thread, thread_context, sampling_buffer, current_cpu_time_ns); - // We can be in one of 2 situations here: - // - // 1. The current sample is the first one after we entered the Waiting for GVL state - // (wall_time_at_previous_sample_ns < abs(gvl_waiting_at)) - // - // time ─────► - // ...──────────────┬───────────────────... - // Other state │ Waiting for GVL - // ...──────────────┴───────────────────... - // ▲ ▲ - // └─ Previous sample └─ This sample - // - // In this case, we'll push two samples: a) one for the current time, b ) an extra sample - // to represent the remaining cpu/wall time before the Waiting for GVL started: - // - // time ─────► - // ...──────────────┬───────────────────... - // Other state │ Waiting for GVL - // ...──────────────┴───────────────────... - // ▲ ▲ ▲ - // └─ Prev... └─ Extra sample └─ This sample - // - // 2. The current sample is the n-th one after we entered the Waiting for GVL state - // (wall_time_at_previous_sample_ns > abs(gvl_waiting_at)) - // - // time ─────► - // ...──────────────┬───────────────────────────────────────────────... - // Other state │ Waiting for GVL - // ...──────────────┴───────────────────────────────────────────────... - // ▲ ▲ ▲ - // └─ Previous sample └─ Previous sample └─ This sample - // - // --- - // - // Overall, gvl_waiting_at will be > 0 if still in the Waiting for GVL state and < 0 if we actually reached the end of - // the wait. - // - // It doesn't really matter if the thread is still waiting or just reached the end of the wait: each sample represents - // a snapshot at time ending now, so if the state finished, it just means the next sample will be a regular one. - - bool is_gvl_waiting_state = gvl_waiting_at != 0 && gvl_waiting_at != GVL_WAITING_ENABLED_EMPTY; - - if (is_gvl_waiting_state) { - if (gvl_waiting_at < 0) { - // Negative means the waiting for GVL just ended, so we clear the state, so next samples no longer represent waiting - rb_internal_thread_specific_set(thread_being_sampled, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); - } - - long gvl_waiting_started_wall_time_ns = labs(gvl_waiting_at); - - if (thread_context->wall_time_at_previous_sample_ns < gvl_waiting_started_wall_time_ns) { // 1 above - long cpu_time_elapsed_ns = update_time_since_previous_sample( - &thread_context->cpu_time_at_previous_sample_ns, - current_cpu_time_ns, - thread_context->gc_tracking.cpu_time_at_start_ns, - IS_NOT_WALL_TIME - ); - - long duration_until_start_of_gvl_waiting_ns = update_time_since_previous_sample( - &thread_context->wall_time_at_previous_sample_ns, - gvl_waiting_started_wall_time_ns, - INVALID_TIME, - IS_WALL_TIME - ); - - // Push extra sample - trigger_sample_for_thread( - state, - thread_being_sampled, - stack_from_thread, - thread_context, - sampling_buffer, - (sample_values) {.cpu_time_ns = cpu_time_elapsed_ns, .cpu_or_wall_samples = 1, .wall_time_ns = duration_until_start_of_gvl_waiting_ns}, - gvl_waiting_started_wall_time_ns, - NULL, - NULL, - false // This is the extra sample before the wait begun; only the next sample will be in the gvl waiting state - ); - } - } - #else - bool is_gvl_waiting_state = false; - #endif - - // Don't assign/update cpu during Waiting for GVL + // Don't assign/update cpu during "Waiting for GVL" long cpu_time_elapsed_ns = is_gvl_waiting_state ? 0 : update_time_since_previous_sample( &thread_context->cpu_time_at_previous_sample_ns, current_cpu_time_ns, @@ -1690,4 +1613,112 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return Qnil; // To allow this to be called from rb_rescue2 } -#endif + + // This method is intended to be called from update_metrics_and_sample. It exists to handle extra sampling steps we + // need to take when sampling cpu/wall-time for a thread that's in the "Waiting for GVL" state. + __attribute__((warn_unused_result)) + static bool handle_gvl_waiting( + struct thread_context_collector_state *state, + VALUE thread_being_sampled, + VALUE stack_from_thread, + struct per_thread_context *thread_context, + sampling_buffer* sampling_buffer, + long current_cpu_time_ns + ) { + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread_being_sampled, per_thread_gvl_waiting_timestamp_key); + + bool is_gvl_waiting_state = gvl_waiting_at != 0 && gvl_waiting_at != GVL_WAITING_ENABLED_EMPTY; + + if (!is_gvl_waiting_state) return false; + + // We can be in one of 2 situations here: + // + // 1. The current sample is the first one after we entered the "Waiting for GVL" state + // (wall_time_at_previous_sample_ns < abs(gvl_waiting_at)) + // + // time ─────► + // ...──────────────┬───────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────... + // ▲ ▲ + // └─ Previous sample └─ Regular sample (caller) + // + // In this case, we'll want to push two samples: a) one for the current time (handled by the caller), b) an extra sample + // to represent the remaining cpu/wall time before the "Waiting for GVL" started: + // + // time ─────► + // ...──────────────┬───────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────... + // ▲ ▲ ▲ + // └─ Prev... └─ Extra sample └─ Regular sample (caller) + // + // 2. The current sample is the n-th one after we entered the "Waiting for GVL" state + // (wall_time_at_previous_sample_ns > abs(gvl_waiting_at)) + // + // time ─────► + // ...──────────────┬───────────────────────────────────────────────... + // Other state │ Waiting for GVL + // ...──────────────┴───────────────────────────────────────────────... + // ▲ ▲ ▲ + // └─ Previous sample └─ Previous sample └─ Regular sample (caller) + // + // In this case, we just report back to the caller that the thread is in the "Waiting for GVL" state. + // + // --- + // + // Overall, gvl_waiting_at will be > 0 if still in the "Waiting for GVL" state and < 0 if we actually reached the end of + // the wait. + // + // It doesn't really matter if the thread is still waiting or just reached the end of the wait: each sample represents + // a snapshot at time ending now, so if the state finished, it just means the next sample will be a regular one. + + if (gvl_waiting_at < 0) { + // Negative means the waiting for GVL just ended, so we clear the state, so next samples no longer represent waiting + rb_internal_thread_specific_set(thread_being_sampled, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); + } + + long gvl_waiting_started_wall_time_ns = labs(gvl_waiting_at); + + if (thread_context->wall_time_at_previous_sample_ns < gvl_waiting_started_wall_time_ns) { // situation 1 above + long cpu_time_elapsed_ns = update_time_since_previous_sample( + &thread_context->cpu_time_at_previous_sample_ns, + current_cpu_time_ns, + thread_context->gc_tracking.cpu_time_at_start_ns, + IS_NOT_WALL_TIME + ); + + long duration_until_start_of_gvl_waiting_ns = update_time_since_previous_sample( + &thread_context->wall_time_at_previous_sample_ns, + gvl_waiting_started_wall_time_ns, + INVALID_TIME, + IS_WALL_TIME + ); + + // Push extra sample + trigger_sample_for_thread( + state, + thread_being_sampled, + stack_from_thread, + thread_context, + sampling_buffer, + (sample_values) {.cpu_time_ns = cpu_time_elapsed_ns, .cpu_or_wall_samples = 1, .wall_time_ns = duration_until_start_of_gvl_waiting_ns}, + gvl_waiting_started_wall_time_ns, + NULL, + NULL, + false // This is the extra sample before the wait begun; only the next sample will be in the gvl waiting state + ); + } + + return true; + } +#else + static bool handle_gvl_waiting( + DDTRACE_UNUSED struct thread_context_collector_state *state, + DDTRACE_UNUSED VALUE thread_being_sampled, + DDTRACE_UNUSED VALUE stack_from_thread, + DDTRACE_UNUSED struct per_thread_context *thread_context, + DDTRACE_UNUSED sampling_buffer* sampling_buffer, + DDTRACE_UNUSED long current_cpu_time_ns, + ) { return false; } +#endif // NO_GVL_INSTRUMENTATION From 30a245b0b7f9ea147482d46e283c7ef011e03220 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 15:57:33 +0100 Subject: [PATCH 15/42] Add testing for `gvl_waiting_at` per-thread initialization --- .../collectors_thread_context.c | 4 ++++ .../collectors/thread_context_spec.rb | 22 +++++++++++++++++++ 2 files changed, 26 insertions(+) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index c6c8833f7df..fc885341672 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -1056,6 +1056,10 @@ static int per_thread_context_as_ruby_hash(st_data_t key_thread, st_data_t value ID2SYM(rb_intern("gc_tracking.cpu_time_at_start_ns")), /* => */ LONG2NUM(thread_context->gc_tracking.cpu_time_at_start_ns), ID2SYM(rb_intern("gc_tracking.wall_time_at_start_ns")), /* => */ LONG2NUM(thread_context->gc_tracking.wall_time_at_start_ns), + + #ifndef NO_GVL_INSTRUMENTATION + ID2SYM(rb_intern("gvl_waiting_at")), /* => */ LONG2NUM((intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key)), + #endif }; for (long unsigned int i = 0; i < VALUE_COUNT(arguments); i += 2) rb_hash_aset(context_as_hash, arguments[i], arguments[i+1]); diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 5c36608eb04..091efcf8213 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -1414,6 +1414,28 @@ def self.otel_sdk_available? # rubocop:enable Style/GlobalVars end end + + describe ":gvl_waiting_at" do + context "on Ruby >= 3.3" do + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } + + it "is initialized to GVL_WAITING_ENABLED_EMPTY (INTPTR_MAX)" do + expect(per_thread_context.values).to all( + include(gvl_waiting_at: 2**63 - 1) # This may need adjusting if we ever support more platforms + ) + end + end + + context "on Ruby < 3.3" do + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION >= "3.3." } + + it "is not set" do + per_thread_context.each do |_thread, context| + expect(context.key?(:gvl_waiting_at)).to be false + end + end + end + end end context "after sampling multiple times" do From 8f610367f921c016574df85821ef63b23ae1144e Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 16:39:22 +0100 Subject: [PATCH 16/42] Add test coverage for `thread_context_collector_on_gvl_waiting` --- .../collectors_thread_context.c | 16 +++++++++ .../collectors/thread_context_spec.rb | 34 +++++++++++++++++++ 2 files changed, 50 insertions(+) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index fc885341672..8f109f247d4 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -256,6 +256,8 @@ static bool handle_gvl_waiting( sampling_buffer* sampling_buffer, long current_cpu_time_ns ); +static VALUE _native_on_gvl_waiting(DDTRACE_UNUSED VALUE self, VALUE thread); +static VALUE _native_gvl_waiting_at_for(DDTRACE_UNUSED VALUE self, VALUE thread); void collectors_thread_context_init(VALUE profiling_module) { VALUE collectors_module = rb_define_module_under(profiling_module, "Collectors"); @@ -287,6 +289,10 @@ void collectors_thread_context_init(VALUE profiling_module) { rb_define_singleton_method(testing_module, "_native_gc_tracking", _native_gc_tracking, 1); rb_define_singleton_method(testing_module, "_native_new_empty_thread", _native_new_empty_thread, 0); rb_define_singleton_method(testing_module, "_native_sample_skipped_allocation_samples", _native_sample_skipped_allocation_samples, 2); + #ifndef NO_GVL_INSTRUMENTATION + rb_define_singleton_method(testing_module, "_native_on_gvl_waiting", _native_on_gvl_waiting, 1); + rb_define_singleton_method(testing_module, "_native_gvl_waiting_at_for", _native_gvl_waiting_at_for, 1); + #endif at_active_span_id = rb_intern_const("@active_span"); at_active_trace_id = rb_intern_const("@active_trace"); @@ -1716,6 +1722,16 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return true; } + + static VALUE _native_on_gvl_waiting(DDTRACE_UNUSED VALUE self, VALUE thread) { + thread_context_collector_on_gvl_waiting(thread); + return Qnil; + } + + static VALUE _native_gvl_waiting_at_for(DDTRACE_UNUSED VALUE self, VALUE thread) { + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); + return INT2NUM(gvl_waiting_at); + } #else static bool handle_gvl_waiting( DDTRACE_UNUSED struct thread_context_collector_state *state, diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 091efcf8213..e4fe6fb8583 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -83,6 +83,14 @@ def sample_skipped_allocation_samples(skipped_samples) described_class::Testing._native_sample_skipped_allocation_samples(cpu_and_wall_time_collector, skipped_samples) end + def on_gvl_waiting(thread) + described_class::Testing._native_on_gvl_waiting(thread) + end + + def gvl_waiting_at_for(thread) + described_class::Testing._native_gvl_waiting_at_for(thread) + end + def thread_list described_class::Testing._native_thread_list end @@ -1242,6 +1250,32 @@ def self.otel_sdk_available? end end + describe "#on_gvl_waiting" do + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } + + context "if a thread has not been sampled before" do + it "does not record anything in the internal_thread_specific value" do + on_gvl_waiting(t1) + + expect(gvl_waiting_at_for(t1)).to be 0 + end + end + + context "after the first sample" do + before { sample } + + it "records the wall-time when gvl waiting started in the thread's internal_thread_specific value" do + wall_time_before_on_gvl_waiting_ns = Datadog::Core::Utils::Time.get_time(:nanosecond) + on_gvl_waiting(t1) + wall_time_after_on_gvl_waiting_ns = Datadog::Core::Utils::Time.get_time(:nanosecond) + + expect(per_thread_context.fetch(t1)).to include( + gvl_waiting_at: be_between(wall_time_before_on_gvl_waiting_ns, wall_time_after_on_gvl_waiting_ns) + ) + end + end + end + describe "#thread_list" do it "returns the same as Ruby's Thread.list" do expect(thread_list).to eq Thread.list From 206b880fc4f805fda2332479bfc0f441a82a6238 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 17:01:34 +0100 Subject: [PATCH 17/42] Add validation that input is thread We're using low-level Ruby APIs that don't look before they jump, so let's be careful to do our own validation to avoid crashes. --- .../collectors_thread_context.c | 4 ++++ .../private_vm_api_access.h | 3 +++ ext/libdatadog_api/datadog_ruby_common.h | 1 - 3 files changed, 7 insertions(+), 1 deletion(-) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 8f109f247d4..f01afa49ede 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -1724,11 +1724,15 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self } static VALUE _native_on_gvl_waiting(DDTRACE_UNUSED VALUE self, VALUE thread) { + ENFORCE_THREAD(thread); + thread_context_collector_on_gvl_waiting(thread); return Qnil; } static VALUE _native_gvl_waiting_at_for(DDTRACE_UNUSED VALUE self, VALUE thread) { + ENFORCE_THREAD(thread); + intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); return INT2NUM(gvl_waiting_at); } diff --git a/ext/datadog_profiling_native_extension/private_vm_api_access.h b/ext/datadog_profiling_native_extension/private_vm_api_access.h index 239465d040b..c40992274cb 100644 --- a/ext/datadog_profiling_native_extension/private_vm_api_access.h +++ b/ext/datadog_profiling_native_extension/private_vm_api_access.h @@ -65,3 +65,6 @@ const char *imemo_kind(VALUE imemo); #ifdef NO_POSTPONED_TRIGGER void *objspace_ptr_for_gc_finalize_deferred_workaround(void); #endif + +#define ENFORCE_THREAD(value) \ + { if (RB_UNLIKELY(!rb_typeddata_is_kind_of(value, RTYPEDDATA_TYPE(rb_thread_current())))) raise_unexpected_type(value, ADD_QUOTES(value), "Thread", __FILE__, __LINE__, __func__); } diff --git a/ext/libdatadog_api/datadog_ruby_common.h b/ext/libdatadog_api/datadog_ruby_common.h index 7a75129d6c2..d2e3d717180 100644 --- a/ext/libdatadog_api/datadog_ruby_common.h +++ b/ext/libdatadog_api/datadog_ruby_common.h @@ -27,7 +27,6 @@ #define ENFORCE_BOOLEAN(value) \ { if (RB_UNLIKELY(value != Qtrue && value != Qfalse)) raise_unexpected_type(value, ADD_QUOTES(value), "true or false", __FILE__, __LINE__, __func__); } -// Called by ENFORCE_TYPE; should not be used directly NORETURN(void raise_unexpected_type(VALUE value, const char *value_name, const char *type_name, const char *file, int line, const char* function_name)); // Helper to retrieve Datadog::VERSION::STRING From e3c113876b047a9d55d515a3ee37452fa97973c9 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 11 Sep 2024 17:21:20 +0100 Subject: [PATCH 18/42] Add testing for `on_gvl_running` --- .../collectors_thread_context.c | 19 +++- .../collectors/thread_context_spec.rb | 91 ++++++++++++++++++- 2 files changed, 105 insertions(+), 5 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index f01afa49ede..6fd8babbd58 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -258,6 +258,7 @@ static bool handle_gvl_waiting( ); static VALUE _native_on_gvl_waiting(DDTRACE_UNUSED VALUE self, VALUE thread); static VALUE _native_gvl_waiting_at_for(DDTRACE_UNUSED VALUE self, VALUE thread); +static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread, VALUE waiting_for_gvl_threshold_ns); void collectors_thread_context_init(VALUE profiling_module) { VALUE collectors_module = rb_define_module_under(profiling_module, "Collectors"); @@ -292,6 +293,7 @@ void collectors_thread_context_init(VALUE profiling_module) { #ifndef NO_GVL_INSTRUMENTATION rb_define_singleton_method(testing_module, "_native_on_gvl_waiting", _native_on_gvl_waiting, 1); rb_define_singleton_method(testing_module, "_native_gvl_waiting_at_for", _native_gvl_waiting_at_for, 1); + rb_define_singleton_method(testing_module, "_native_on_gvl_running", _native_on_gvl_running, 2); #endif at_active_span_id = rb_intern_const("@active_span"); @@ -1561,7 +1563,7 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self // This function can get called from outside the GVL and even on non-main Ractors __attribute__((warn_unused_result)) - bool thread_context_collector_on_gvl_running(VALUE thread) { + bool thread_context_collector_on_gvl_running_with_threshold(VALUE thread, uint32_t waiting_for_gvl_threshold_ns) { intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); // Thread was not being profiled / not waiting on gvl @@ -1572,7 +1574,7 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - gvl_waiting_at; - bool should_sample = waiting_for_gvl_duration_ns >= WAITING_FOR_GVL_THRESHOLD_NS; + bool should_sample = waiting_for_gvl_duration_ns >= waiting_for_gvl_threshold_ns; if (should_sample) { // We flip the gvl_waiting_at to negative to mark that the thread is now running @@ -1587,6 +1589,11 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return should_sample; } + __attribute__((warn_unused_result)) + bool thread_context_collector_on_gvl_running(VALUE thread) { + return thread_context_collector_on_gvl_running_with_threshold(thread, WAITING_FOR_GVL_THRESHOLD_NS); + } + VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { struct thread_context_collector_state *state; TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); @@ -1734,7 +1741,13 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self ENFORCE_THREAD(thread); intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(thread, per_thread_gvl_waiting_timestamp_key); - return INT2NUM(gvl_waiting_at); + return LONG2NUM(gvl_waiting_at); + } + + static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread, VALUE waiting_for_gvl_threshold_ns) { + ENFORCE_THREAD(thread); + + return thread_context_collector_on_gvl_running_with_threshold(thread, NUM2UINT(waiting_for_gvl_threshold_ns)) ? Qtrue : Qfalse; } #else static bool handle_gvl_waiting( diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index e4fe6fb8583..4334d7bf608 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -40,6 +40,9 @@ let(:endpoint_collection_enabled) { true } let(:timeline_enabled) { false } let(:allocation_type_enabled) { true } + # This mirrors the use of INTPTR_MAX for GVL_WAITING_ENABLED_EMPTY in the native code; it may need adjusting if we ever + # want to support more platforms + let(:gvl_waiting_enabled_empty_magic_value) { 2**63 - 1 } subject(:cpu_and_wall_time_collector) do described_class.new( @@ -91,6 +94,10 @@ def gvl_waiting_at_for(thread) described_class::Testing._native_gvl_waiting_at_for(thread) end + def on_gvl_running(thread, waiting_for_gvl_threshold_ns) + described_class::Testing._native_on_gvl_running(thread, waiting_for_gvl_threshold_ns) + end + def thread_list described_class::Testing._native_thread_list end @@ -1253,7 +1260,7 @@ def self.otel_sdk_available? describe "#on_gvl_waiting" do before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } - context "if a thread has not been sampled before" do + context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do on_gvl_waiting(t1) @@ -1276,6 +1283,86 @@ def self.otel_sdk_available? end end + describe "#on_gvl_running" do + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } + + context "if thread has not been sampled before" do + it "does not record anything in the internal_thread_specific value" do + on_gvl_running(t1, 0) + + expect(gvl_waiting_at_for(t1)).to be 0 + end + end + + context "when the internal_thread_specific value is GVL_WAITING_ENABLED_EMPTY" do + before do + sample + expect(gvl_waiting_at_for(t1)).to eq gvl_waiting_enabled_empty_magic_value + end + + it do + expect { on_gvl_running(t1, 0) }.to_not change { gvl_waiting_at_for(t1) } + end + + it "does not flag that a sample is needed" do + expect(on_gvl_running(t1, 0)).to be false + end + end + + context "when the thread was Waiting on GVL" do + before do + sample + on_gvl_waiting(t1) + @gvl_waiting_at = gvl_waiting_at_for(t1) + expect(@gvl_waiting_at).to be > 0 + end + + context "when Waiting for GVL duration >= the threshold" do + let(:threshold) { 0 } + + it "flips the value of gvl_waiting_at to negative" do + expect { on_gvl_running(t1, threshold) } + .to change { gvl_waiting_at_for(t1) } + .from(@gvl_waiting_at) + .to(-@gvl_waiting_at) + end + + it "flags that a sample is needed" do + expect(on_gvl_running(t1, threshold)).to be true + end + + context "when called several times in a row" do + before { on_gvl_running(t1, threshold) } + + it "flags that a sample is needed" do + expect(on_gvl_running(t1, threshold)).to be true + end + + it "keeps the value of gvl_waiting_at as negative" do + on_gvl_running(t1, threshold) + + expect(gvl_waiting_at_for(t1)).to be(-@gvl_waiting_at) + end + end + end + + context "when Waiting for GVL duration < the threshold" do + let(:threshold) { 1_000_000_000 } + + it "resets the value of gvl_waiting_at back to GVL_WAITING_ENABLED_EMPTY" do + expect { on_gvl_running(t1, threshold) } + .to change { gvl_waiting_at_for(t1) } + .from(@gvl_waiting_at) + .to(gvl_waiting_enabled_empty_magic_value) + end + + it "flags that a sample is not needed" do + expect(on_gvl_running(t1, threshold)).to be false + end + end + end + end + describe "#thread_list" do it "returns the same as Ruby's Thread.list" do expect(thread_list).to eq Thread.list @@ -1455,7 +1542,7 @@ def self.otel_sdk_available? it "is initialized to GVL_WAITING_ENABLED_EMPTY (INTPTR_MAX)" do expect(per_thread_context.values).to all( - include(gvl_waiting_at: 2**63 - 1) # This may need adjusting if we ever support more platforms + include(gvl_waiting_at: gvl_waiting_enabled_empty_magic_value) ) end end From 1bf601458dd1a884634e1575457cb8d9e527a2b3 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 09:24:55 +0100 Subject: [PATCH 19/42] Extract out ruby version for GVL profiling specs It occurs to me that I'm sprinkling a lot of conditionals all over the place, and when we want to support 3.2 we'll need to find all of them and if we miss some there won't be anything reminding us it's missing. So by extracting the version to a single location, we'll bump it once and all specs that need to work for 3.2 will be run. --- spec/datadog/profiling/collectors/thread_context_spec.rb | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 4334d7bf608..36b33863f78 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -40,6 +40,7 @@ let(:endpoint_collection_enabled) { true } let(:timeline_enabled) { false } let(:allocation_type_enabled) { true } + let(:minimum_ruby_for_gvl_profiling) { "3.3." } # This mirrors the use of INTPTR_MAX for GVL_WAITING_ENABLED_EMPTY in the native code; it may need adjusting if we ever # want to support more platforms let(:gvl_waiting_enabled_empty_magic_value) { 2**63 - 1 } @@ -1258,7 +1259,7 @@ def self.otel_sdk_available? end describe "#on_gvl_waiting" do - before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } + before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling > RUBY_VERSION } context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do @@ -1284,7 +1285,7 @@ def self.otel_sdk_available? end describe "#on_gvl_running" do - before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } + before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling > RUBY_VERSION } context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do @@ -1538,7 +1539,7 @@ def self.otel_sdk_available? describe ":gvl_waiting_at" do context "on Ruby >= 3.3" do - before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } + before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling > RUBY_VERSION } it "is initialized to GVL_WAITING_ENABLED_EMPTY (INTPTR_MAX)" do expect(per_thread_context.values).to all( @@ -1548,7 +1549,7 @@ def self.otel_sdk_available? end context "on Ruby < 3.3" do - before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION >= "3.3." } + before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling <= RUBY_VERSION } it "is not set" do per_thread_context.each do |_thread, context| From 7faab4263f4074102ac7c29c049e2ebc9e0381b3 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 11:31:19 +0100 Subject: [PATCH 20/42] Add test coverage for samples during/after Waiting for GVL --- .../collectors/thread_context_spec.rb | 134 +++++++++++++++++- spec/datadog/profiling/spec_helper.rb | 14 +- 2 files changed, 144 insertions(+), 4 deletions(-) diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 36b33863f78..db48c3f73fc 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -760,6 +760,136 @@ def self.otel_sdk_available? expect(samples.first.labels).to include(end_timestamp_ns: be_between(time_before, time_after)) end + + context "when thread starts Waiting for GVL" do + before do + sample # trigger context creation + samples_from_pprof(recorder.serialize!) # flush sample + + @previous_sample_timestamp_ns = per_thread_context.dig(t1, :wall_time_at_previous_sample_ns) + + @time_before_gvl_waiting = Datadog::Core::Utils::Time.as_utc_epoch_ns(Time.now) + on_gvl_waiting(t1) + @time_after_gvl_waiting = Datadog::Core::Utils::Time.as_utc_epoch_ns(Time.now) + + @gvl_waiting_at = gvl_waiting_at_for(t1) + + expect(@gvl_waiting_at).to be >= @previous_sample_timestamp_ns + end + + it "records a first sample to represent the time between the previous sample and the start of Waiting for GVL" do + sample + + first_sample = samples_for_thread(samples, t1, expected_size: 2).first + + expect(first_sample.values.fetch(:"wall-time")).to be(@gvl_waiting_at - @previous_sample_timestamp_ns) + expect(first_sample.labels).to include( + state: "sleeping", + end_timestamp_ns: be_between(@time_before_gvl_waiting, @time_after_gvl_waiting), + ) + end + + it "records a second sample to represent the time spent Waiting for GVL" do + time_before_sample = Datadog::Core::Utils::Time.as_utc_epoch_ns(Time.now) + sample + time_after_sample = Datadog::Core::Utils::Time.as_utc_epoch_ns(Time.now) + + second_sample = samples_for_thread(samples, t1, expected_size: 2).last + + expect(second_sample.values.fetch(:"wall-time")).to be(per_thread_context.dig(t1, :wall_time_at_previous_sample_ns) - @gvl_waiting_at) + expect(second_sample.labels).to include( + state: "waiting for gvl", + end_timestamp_ns: be_between(time_before_sample, time_after_sample), + ) + end + end + + context "when thread is Waiting for GVL" do + before do + sample # trigger context creation + on_gvl_waiting(t1) + sample # trigger creation of sample representing the period before Waiting for GVL + samples_from_pprof(recorder.serialize!) # flush previous samples + end + + def sample_and_check(expected_state:) + monotonic_time_before_sample = per_thread_context.dig(t1, :wall_time_at_previous_sample_ns) + time_before_sample = Datadog::Core::Utils::Time.as_utc_epoch_ns(Time.now) + monotonic_time_sanity_check = Datadog::Core::Utils::Time.get_time(:nanosecond) + + sample + + time_after_sample = Datadog::Core::Utils::Time.as_utc_epoch_ns(Time.now) + monotonic_time_after_sample = per_thread_context.dig(t1, :wall_time_at_previous_sample_ns) + + expect(monotonic_time_after_sample).to be >= monotonic_time_sanity_check + + latest_sample = sample_for_thread(samples_from_pprof(recorder.serialize!), t1) + + expect(latest_sample.values.fetch(:"wall-time")).to be(monotonic_time_after_sample - monotonic_time_before_sample) + expect(latest_sample.labels).to include( + state: expected_state, + end_timestamp_ns: be_between(time_before_sample, time_after_sample), + ) + end + + it "records a new Waiting for GVL sample on every subsequent sample" do + 3.times { sample_and_check(expected_state: "waiting for gvl") } + end + + it "does not change the gvl_waiting_at" do + value_before = gvl_waiting_at_for(t1) + + sample + + expect(gvl_waiting_at_for(t1)).to be value_before + expect(gvl_waiting_at_for(t1)).to be > 0 + end + + context "when thread is ready to run again" do + before do + on_gvl_running(t1, threshold) + end + + context "when Waiting for GVL duration >= the threshold" do + let(:threshold) { 0 } + + it "records a last Waiting for GVL sample" do + sample_and_check(expected_state: "waiting for gvl") + end + + it "resets the gvl_waiting_at to GVL_WAITING_ENABLED_EMPTY" do + expect(gvl_waiting_at_for(t1)).to be < 0 + + expect { sample }.to change { gvl_waiting_at_for(t1) }.from(gvl_waiting_at_for(t1)).to(gvl_waiting_enabled_empty_magic_value) + end + + it "does not record a new Waiting for GVL sample afterwards" do + sample # last Waiting for GVL sample + samples_from_pprof(recorder.serialize!) # flush previous samples + + 3.times { sample_and_check(expected_state: "sleeping") } + end + end + + context "when Waiting for GVL duration < the threshold" do + let(:threshold) { 1_000_000_000 } + + it "records a regular sample" do + expect(gvl_waiting_at_for(t1)).to eq gvl_waiting_enabled_empty_magic_value + + # This is a rare situation (but can still happen) -- the thread was Waiting for GVL on the previous sample, + # but the overall duration of the Waiting for GVL was below the threshold. This means that on_gvl_running + # clears the Waiting for GVL state, and the next sample is immediately back to being a regular sample. + # + # Because the state has been cleared immediately, the next sample is a regular one. We effectively ignore + # a small time period that was still Waiting for GVL as a means to reduce overhead. + + sample_and_check(expected_state: "sleeping") + end + end + end + end end end end @@ -1538,7 +1668,7 @@ def self.otel_sdk_available? end describe ":gvl_waiting_at" do - context "on Ruby >= 3.3" do + context "on supported Rubies" do before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling > RUBY_VERSION } it "is initialized to GVL_WAITING_ENABLED_EMPTY (INTPTR_MAX)" do @@ -1548,7 +1678,7 @@ def self.otel_sdk_available? end end - context "on Ruby < 3.3" do + context "on legacy Rubies" do before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling <= RUBY_VERSION } it "is not set" do diff --git a/spec/datadog/profiling/spec_helper.rb b/spec/datadog/profiling/spec_helper.rb index ca7ecdc35e7..3eb5e4cecda 100644 --- a/spec/datadog/profiling/spec_helper.rb +++ b/spec/datadog/profiling/spec_helper.rb @@ -79,11 +79,21 @@ def object_id_from(thread_id) end end - def samples_for_thread(samples, thread) - samples.select do |sample| + def samples_for_thread(samples, thread, expected_size: nil) + result = samples.select do |sample| thread_id = sample.labels[:"thread id"] thread_id && object_id_from(thread_id) == thread.object_id end + + if expected_size + expect(result.size).to(be(expected_size), "Found unexpected sample count in result: #{result}") + end + + result + end + + def sample_for_thread(samples, thread) + samples_for_thread(samples, thread, expected_size: 1).first end # We disable heap_sample collection by default in tests since it requires some extra mocking/ From f9c919abf9b0d73e6c604ea7f02a6d96ef60fc79 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 15:24:49 +0100 Subject: [PATCH 21/42] Add test coverage and explain why `sample_after_gvl_running` is needed --- .../collectors_thread_context.c | 45 ++++++++++- .../collectors/thread_context_spec.rb | 78 +++++++++++++++++++ 2 files changed, 119 insertions(+), 4 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 6fd8babbd58..54adc4a682c 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -259,6 +259,7 @@ static bool handle_gvl_waiting( static VALUE _native_on_gvl_waiting(DDTRACE_UNUSED VALUE self, VALUE thread); static VALUE _native_gvl_waiting_at_for(DDTRACE_UNUSED VALUE self, VALUE thread); static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread, VALUE waiting_for_gvl_threshold_ns); +static VALUE _native_sample_after_gvl_running(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread); void collectors_thread_context_init(VALUE profiling_module) { VALUE collectors_module = rb_define_module_under(profiling_module, "Collectors"); @@ -294,6 +295,7 @@ void collectors_thread_context_init(VALUE profiling_module) { rb_define_singleton_method(testing_module, "_native_on_gvl_waiting", _native_on_gvl_waiting, 1); rb_define_singleton_method(testing_module, "_native_gvl_waiting_at_for", _native_gvl_waiting_at_for, 1); rb_define_singleton_method(testing_module, "_native_on_gvl_running", _native_on_gvl_running, 2); + rb_define_singleton_method(testing_module, "_native_sample_after_gvl_running", _native_sample_after_gvl_running, 2); #endif at_active_span_id = rb_intern_const("@active_span"); @@ -1594,13 +1596,38 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return thread_context_collector_on_gvl_running_with_threshold(thread, WAITING_FOR_GVL_THRESHOLD_NS); } - VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { + // Why does this method need to exist? + // + // You may be surprised to see that if you never call this method, Waiting for GVL samples will still show up. + // This is because regular cpu/wall-time samples also use `update_metrics_and_sample` which will push those samples + // as needed. + // + // The reason this method needs to exist and be called very shortly after thread_context_collector_on_gvl_running + // returning true is the accuracy of the timing and stack for the Waiting for GVL to end. + // + // Timing: + // Because we currently only record when the Waiting for GVL started and not when the Waiting for GVL ended, + // we rely on pushing a sample as soon as possible when the Waiting for GVL ends so that the timestamp of the sample + // is close to the timestamp of finish the Waiting for GVL. + // + // Stack: + // If the thread starts working without the end of the Waiting for GVL sample, then by the time that sample happens + // (via the regular cpu/wall-time samples mechanism), the stack can be be inaccurate. + // + // Arguably, the last sample after Waiting for GVL ended (when gvl_waiting_at < 0) should always come from this method + // and not a regular cpu/wall-time sample BUT since all of these things are happening in parallel I suspect + // it's possible for a regular sample to kick in just before this one. + // + // --- + // + // NOTE: In normal use, current_thread is expected to be == rb_thread_current(); using a different thread is only + // to make testing easier. + VALUE thread_context_collector_sample_after_gvl_running_with_thread(VALUE self_instance, VALUE current_thread) { struct thread_context_collector_state *state; TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); if (!state->timeline_enabled) rb_raise(rb_eRuntimeError, "gvl profiling requires timeline to be enabled"); - VALUE current_thread = rb_thread_current(); struct per_thread_context *thread_context = get_or_create_context_for(current_thread, state); intptr_t gvl_waiting_at = (intptr_t) rb_internal_thread_specific_get(current_thread, per_thread_gvl_waiting_timestamp_key); @@ -1610,7 +1637,7 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self // that ran `thread_context_collector_on_gvl_running` and made the decision to sample OR a regular sample was // triggered ahead of us. // We do nothing in this case. - return Qnil; + return Qfalse; } // We don't actually account for cpu-time during Waiting for GVL. BUT, we may chose to push an @@ -1628,7 +1655,11 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self monotonic_wall_time_now_ns(RAISE_ON_FAILURE) ); - return Qnil; // To allow this to be called from rb_rescue2 + return Qtrue; // To allow this to be called from rb_rescue2 + } + + VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance) { + return thread_context_collector_sample_after_gvl_running_with_thread(self_instance, rb_thread_current()); } // This method is intended to be called from update_metrics_and_sample. It exists to handle extra sampling steps we @@ -1749,6 +1780,12 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return thread_context_collector_on_gvl_running_with_threshold(thread, NUM2UINT(waiting_for_gvl_threshold_ns)) ? Qtrue : Qfalse; } + + static VALUE _native_sample_after_gvl_running(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread) { + ENFORCE_THREAD(thread); + + return thread_context_collector_sample_after_gvl_running_with_thread(collector_instance, thread); + } #else static bool handle_gvl_waiting( DDTRACE_UNUSED struct thread_context_collector_state *state, diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index db48c3f73fc..2ae76eeca3e 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -99,6 +99,10 @@ def on_gvl_running(thread, waiting_for_gvl_threshold_ns) described_class::Testing._native_on_gvl_running(thread, waiting_for_gvl_threshold_ns) end + def sample_after_gvl_running(thread) + described_class::Testing._native_sample_after_gvl_running(cpu_and_wall_time_collector, thread) + end + def thread_list described_class::Testing._native_thread_list end @@ -1494,6 +1498,80 @@ def sample_and_check(expected_state:) end end + describe "#sample_after_gvl_running" do + let(:timeline_enabled) { true } + + context "when thread does not have the end of Waiting for GVL to be recorded" do + before do + expect(gvl_waiting_at_for(t1)).to be 0 + end + + it do + expect(sample_after_gvl_running(t1)).to be false + end + + it "does not sample the thread" do + sample_after_gvl_running(t1) + + expect(samples).to be_empty + end + end + + # @ivoanjo: The behavior here is expected to be (in terms of wall-time accounting and timestamps) exactly the same + # as for #sample. That's because both call the same underlying `update_metrics_and_sample` method to do the work. + # + # See the big comment next to the definition of `thread_context_collector_sample_after_gvl_running_with_thread` + # for why we need a separate `sample_after_gvl_running`. + # + # Thus, I chose to not repeat the extensive Waiting for GVL asserts we already have in #sample, and do a smaller pass. + context "when thread has the end of Waiting for GVL to be recorded (and a start was not yet recorded)" do + before do + sample # trigger context creation + on_gvl_waiting(t1) + + sample if record_start + + on_gvl_running(t1, 0) + samples_from_pprof(recorder.serialize!) # flush samples + + expect(gvl_waiting_at_for(t1)).to be < 0 + end + + context "when a start was not yet recorded" do + let(:record_start) { false } + + it do + expect(sample_after_gvl_running(t1)).to be true + end + + it "records a sample to represent the time prior to Waiting for GVL, and another to represent the waiting" do + sample_after_gvl_running(t1) + + expect(samples.size).to be 2 + + expect(samples.first.labels).to include(state: "sleeping") + expect(samples.last.labels).to include(state: "waiting for gvl") + end + end + + context "when a start was already recorded" do + let(:record_start) { true } + + it do + expect(sample_after_gvl_running(t1)).to be true + end + + it "records a sample to represent the Waiting for GVL" do + sample_after_gvl_running(t1) + + expect(samples.size).to be 1 + + expect(samples.first.labels).to include(state: "waiting for gvl") + end + end + end + end + describe "#thread_list" do it "returns the same as Ruby's Thread.list" do expect(thread_list).to eq Thread.list From 22a54aeee73a4a00c811be2636ba38f3b6d41ed4 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 16:06:57 +0100 Subject: [PATCH 22/42] Add test coverage for cpu-time behavior --- .../collectors_thread_context.c | 17 ++++++ .../collectors/thread_context_spec.rb | 57 +++++++++++++++++++ 2 files changed, 74 insertions(+) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 54adc4a682c..67fa9279df2 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -260,6 +260,7 @@ static VALUE _native_on_gvl_waiting(DDTRACE_UNUSED VALUE self, VALUE thread); static VALUE _native_gvl_waiting_at_for(DDTRACE_UNUSED VALUE self, VALUE thread); static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread, VALUE waiting_for_gvl_threshold_ns); static VALUE _native_sample_after_gvl_running(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread); +static VALUE _native_apply_delta_to_cpu_time_at_previous_sample_ns(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread, VALUE delta_ns); void collectors_thread_context_init(VALUE profiling_module) { VALUE collectors_module = rb_define_module_under(profiling_module, "Collectors"); @@ -296,6 +297,7 @@ void collectors_thread_context_init(VALUE profiling_module) { rb_define_singleton_method(testing_module, "_native_gvl_waiting_at_for", _native_gvl_waiting_at_for, 1); rb_define_singleton_method(testing_module, "_native_on_gvl_running", _native_on_gvl_running, 2); rb_define_singleton_method(testing_module, "_native_sample_after_gvl_running", _native_sample_after_gvl_running, 2); + rb_define_singleton_method(testing_module, "_native_apply_delta_to_cpu_time_at_previous_sample_ns", _native_apply_delta_to_cpu_time_at_previous_sample_ns, 3); #endif at_active_span_id = rb_intern_const("@active_span"); @@ -1786,6 +1788,21 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return thread_context_collector_sample_after_gvl_running_with_thread(collector_instance, thread); } + + static VALUE _native_apply_delta_to_cpu_time_at_previous_sample_ns(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread, VALUE delta_ns) { + ENFORCE_THREAD(thread); + + struct thread_context_collector_state *state; + TypedData_Get_Struct(collector_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); + + struct per_thread_context *thread_context = get_context_for(thread, state); + if (thread_context == NULL) rb_raise(rb_eArgError, "Unexpected: This method cannot be used unless the per-thread context for the thread already exists"); + + thread_context->cpu_time_at_previous_sample_ns += NUM2LONG(delta_ns); + + return Qtrue; + } + #else static bool handle_gvl_waiting( DDTRACE_UNUSED struct thread_context_collector_state *state, diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 2ae76eeca3e..80cc0eb9443 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -119,6 +119,10 @@ def gc_tracking described_class::Testing._native_gc_tracking(cpu_and_wall_time_collector) end + def apply_delta_to_cpu_time_at_previous_sample_ns(thread, delta_ns) + described_class::Testing._native_apply_delta_to_cpu_time_at_previous_sample_ns(cpu_and_wall_time_collector, thread, delta_ns) + end + # This method exists only so we can look for its name in the stack trace in a few tests def inside_t1 yield @@ -806,6 +810,23 @@ def self.otel_sdk_available? end_timestamp_ns: be_between(time_before_sample, time_after_sample), ) end + + context "cpu-time behavior on Linux" do + before do + skip "Test only runs on Linux" unless PlatformHelpers.linux? + + apply_delta_to_cpu_time_at_previous_sample_ns(t1, -12345) # Rewind back cpu-clock since previous sample + end + + it "assigns all the cpu-time to the sample before Waiting for GVL started" do + sample + + first_sample, second_sample = samples_for_thread(samples, t1, expected_size: 2) + + expect(first_sample.values.fetch(:"cpu-time")).to be 12345 + expect(second_sample.values.fetch(:"cpu-time")).to be 0 + end + end end context "when thread is Waiting for GVL" do @@ -835,6 +856,8 @@ def sample_and_check(expected_state:) state: expected_state, end_timestamp_ns: be_between(time_before_sample, time_after_sample), ) + + latest_sample end it "records a new Waiting for GVL sample on every subsequent sample" do @@ -850,6 +873,22 @@ def sample_and_check(expected_state:) expect(gvl_waiting_at_for(t1)).to be > 0 end + context "cpu-time behavior on Linux" do + before do + skip "Test only runs on Linux" unless PlatformHelpers.linux? + + apply_delta_to_cpu_time_at_previous_sample_ns(t1, -12345) # Rewind back cpu-clock since previous sample + end + + it "does not assign any cpu-time to the Waiting for GVL samples" do + 3.times do + latest_sample = sample_and_check(expected_state: "waiting for gvl") + + expect(latest_sample.values.fetch(:"cpu-time")).to be 0 + end + end + end + context "when thread is ready to run again" do before do on_gvl_running(t1, threshold) @@ -874,6 +913,24 @@ def sample_and_check(expected_state:) 3.times { sample_and_check(expected_state: "sleeping") } end + + context "cpu-time behavior on Linux" do + before do + skip "Test only runs on Linux" unless PlatformHelpers.linux? + end + + it "assigns all the cpu-time to samples only after Waiting for GVL ends" do + apply_delta_to_cpu_time_at_previous_sample_ns(t1, -12345) # Rewind back cpu-clock since previous sample + + sample # last Waiting for GVL sample + + latest_sample = sample_for_thread(samples_from_pprof(recorder.serialize!), t1) + expect(latest_sample.values.fetch(:"cpu-time")).to be 0 + + latest_sample = sample_and_check(expected_state: "had cpu") + expect(latest_sample.values.fetch(:"cpu-time")).to be 12345 + end + end end context "when Waiting for GVL duration < the threshold" do From a6f6646bd78428e0414ac43234a7f4350fbd53ee Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 16:11:12 +0100 Subject: [PATCH 23/42] Sync `datadog_ruby_common.h` header changes --- ext/datadog_profiling_native_extension/datadog_ruby_common.h | 1 - 1 file changed, 1 deletion(-) diff --git a/ext/datadog_profiling_native_extension/datadog_ruby_common.h b/ext/datadog_profiling_native_extension/datadog_ruby_common.h index 7a75129d6c2..d2e3d717180 100644 --- a/ext/datadog_profiling_native_extension/datadog_ruby_common.h +++ b/ext/datadog_profiling_native_extension/datadog_ruby_common.h @@ -27,7 +27,6 @@ #define ENFORCE_BOOLEAN(value) \ { if (RB_UNLIKELY(value != Qtrue && value != Qfalse)) raise_unexpected_type(value, ADD_QUOTES(value), "true or false", __FILE__, __LINE__, __func__); } -// Called by ENFORCE_TYPE; should not be used directly NORETURN(void raise_unexpected_type(VALUE value, const char *value_name, const char *type_name, const char *file, int line, const char* function_name)); // Helper to retrieve Datadog::VERSION::STRING From e6093c8f16f1b31c9d8c1901903154e6d2f0660b Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 16:21:01 +0100 Subject: [PATCH 24/42] Linting fixes --- .../collectors/thread_context_spec.rb | 25 +++++++++++-------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 80cc0eb9443..dccda860608 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -40,7 +40,7 @@ let(:endpoint_collection_enabled) { true } let(:timeline_enabled) { false } let(:allocation_type_enabled) { true } - let(:minimum_ruby_for_gvl_profiling) { "3.3." } + let(:min_ruby_for_gvl_profiling) { "3.3." } # This mirrors the use of INTPTR_MAX for GVL_WAITING_ENABLED_EMPTY in the native code; it may need adjusting if we ever # want to support more platforms let(:gvl_waiting_enabled_empty_magic_value) { 2**63 - 1 } @@ -120,7 +120,8 @@ def gc_tracking end def apply_delta_to_cpu_time_at_previous_sample_ns(thread, delta_ns) - described_class::Testing._native_apply_delta_to_cpu_time_at_previous_sample_ns(cpu_and_wall_time_collector, thread, delta_ns) + described_class::Testing + ._native_apply_delta_to_cpu_time_at_previous_sample_ns(cpu_and_wall_time_collector, thread, delta_ns) end # This method exists only so we can look for its name in the stack trace in a few tests @@ -804,7 +805,8 @@ def self.otel_sdk_available? second_sample = samples_for_thread(samples, t1, expected_size: 2).last - expect(second_sample.values.fetch(:"wall-time")).to be(per_thread_context.dig(t1, :wall_time_at_previous_sample_ns) - @gvl_waiting_at) + expect(second_sample.values.fetch(:"wall-time")) + .to be(per_thread_context.dig(t1, :wall_time_at_previous_sample_ns) - @gvl_waiting_at) expect(second_sample.labels).to include( state: "waiting for gvl", end_timestamp_ns: be_between(time_before_sample, time_after_sample), @@ -851,7 +853,8 @@ def sample_and_check(expected_state:) latest_sample = sample_for_thread(samples_from_pprof(recorder.serialize!), t1) - expect(latest_sample.values.fetch(:"wall-time")).to be(monotonic_time_after_sample - monotonic_time_before_sample) + expect(latest_sample.values.fetch(:"wall-time")) + .to be(monotonic_time_after_sample - monotonic_time_before_sample) expect(latest_sample.labels).to include( state: expected_state, end_timestamp_ns: be_between(time_before_sample, time_after_sample), @@ -904,7 +907,9 @@ def sample_and_check(expected_state:) it "resets the gvl_waiting_at to GVL_WAITING_ENABLED_EMPTY" do expect(gvl_waiting_at_for(t1)).to be < 0 - expect { sample }.to change { gvl_waiting_at_for(t1) }.from(gvl_waiting_at_for(t1)).to(gvl_waiting_enabled_empty_magic_value) + expect { sample }.to change { gvl_waiting_at_for(t1) } + .from(gvl_waiting_at_for(t1)) + .to(gvl_waiting_enabled_empty_magic_value) end it "does not record a new Waiting for GVL sample afterwards" do @@ -1450,7 +1455,7 @@ def sample_and_check(expected_state:) end describe "#on_gvl_waiting" do - before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling > RUBY_VERSION } + before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do @@ -1476,7 +1481,7 @@ def sample_and_check(expected_state:) end describe "#on_gvl_running" do - before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling > RUBY_VERSION } + before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do @@ -1493,7 +1498,7 @@ def sample_and_check(expected_state:) end it do - expect { on_gvl_running(t1, 0) }.to_not change { gvl_waiting_at_for(t1) } + expect { on_gvl_running(t1, 0) }.to_not(change { gvl_waiting_at_for(t1) }) end it "does not flag that a sample is needed" do @@ -1804,7 +1809,7 @@ def sample_and_check(expected_state:) describe ":gvl_waiting_at" do context "on supported Rubies" do - before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling > RUBY_VERSION } + before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } it "is initialized to GVL_WAITING_ENABLED_EMPTY (INTPTR_MAX)" do expect(per_thread_context.values).to all( @@ -1814,7 +1819,7 @@ def sample_and_check(expected_state:) end context "on legacy Rubies" do - before { skip "Behavior does not apply to current Ruby version" if minimum_ruby_for_gvl_profiling <= RUBY_VERSION } + before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling <= RUBY_VERSION } it "is not set" do per_thread_context.each do |_thread, context| From e0ceba55bc4a00f99fee53c43e98c0166ae53a45 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 16:26:42 +0100 Subject: [PATCH 25/42] Restore support for legacy Rubies --- .../collectors_thread_context.c | 2 +- spec/datadog/profiling/collectors/thread_context_spec.rb | 6 ++++++ 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 67fa9279df2..2b98bd1d510 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -1810,6 +1810,6 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self DDTRACE_UNUSED VALUE stack_from_thread, DDTRACE_UNUSED struct per_thread_context *thread_context, DDTRACE_UNUSED sampling_buffer* sampling_buffer, - DDTRACE_UNUSED long current_cpu_time_ns, + DDTRACE_UNUSED long current_cpu_time_ns ) { return false; } #endif // NO_GVL_INSTRUMENTATION diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index dccda860608..b2b5841a693 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -772,6 +772,8 @@ def self.otel_sdk_available? context "when thread starts Waiting for GVL" do before do + skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION + sample # trigger context creation samples_from_pprof(recorder.serialize!) # flush sample @@ -833,6 +835,8 @@ def self.otel_sdk_available? context "when thread is Waiting for GVL" do before do + skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION + sample # trigger context creation on_gvl_waiting(t1) sample # trigger creation of sample representing the period before Waiting for GVL @@ -1561,6 +1565,8 @@ def sample_and_check(expected_state:) end describe "#sample_after_gvl_running" do + before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } + let(:timeline_enabled) { true } context "when thread does not have the end of Waiting for GVL to be recorded" do From 147f227f67721e024fa6c818a753008629f0eecf Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 16:26:55 +0100 Subject: [PATCH 26/42] Minor spec cleanups --- spec/datadog/profiling/collectors/thread_context_spec.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index b2b5841a693..5c9fb81fbdf 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -1569,7 +1569,7 @@ def sample_and_check(expected_state:) let(:timeline_enabled) { true } - context "when thread does not have the end of Waiting for GVL to be recorded" do + context "when thread is not at the end of a Waiting for GVL period" do before do expect(gvl_waiting_at_for(t1)).to be 0 end @@ -1592,7 +1592,7 @@ def sample_and_check(expected_state:) # for why we need a separate `sample_after_gvl_running`. # # Thus, I chose to not repeat the extensive Waiting for GVL asserts we already have in #sample, and do a smaller pass. - context "when thread has the end of Waiting for GVL to be recorded (and a start was not yet recorded)" do + context "when thread is at the end of a Waiting for GVL period" do before do sample # trigger context creation on_gvl_waiting(t1) From 61010528d680a3cd98cf327c740d798babc4102b Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 12 Sep 2024 17:30:35 +0100 Subject: [PATCH 27/42] Refactor: Introduce `ThreadContext.for_testing` constructor So far in the profiler, we've been avoiding adding defaults to keyword arguments that are expected to be set in production as, well, those defaults won't match what happens in production (they'll get overridden). This is all fine, but quite annoying when we use our components piecemeal for benchmarking and testing, since adding any new arguments means modifying a gazillion places in the codebase to start passing in that argument. To solve this, let's introduce a `for_testing` helper method that provides defaults that we often use for testing, and that then calls into the regular constructor. --- benchmarks/profiler_gc.rb | 4 +--- benchmarks/profiler_sample_loop_v2.rb | 4 +--- benchmarks/profiler_sample_serialize.rb | 4 +--- .../profiling/collectors/thread_context.rb | 18 ++++++++++++++++++ .../cpu_and_wall_time_worker_spec.rb | 14 ++------------ 5 files changed, 23 insertions(+), 21 deletions(-) diff --git a/benchmarks/profiler_gc.rb b/benchmarks/profiler_gc.rb index 8fa1ee615a9..e3fca987758 100644 --- a/benchmarks/profiler_gc.rb +++ b/benchmarks/profiler_gc.rb @@ -17,9 +17,7 @@ def create_profiler heap_sample_every: 1, timeline_enabled: true, ) - @collector = Datadog::Profiling::Collectors::ThreadContext.new( - recorder: @recorder, max_frames: 400, tracer: nil, endpoint_collection_enabled: false, timeline_enabled: true - ) + @collector = Datadog::Profiling::Collectors::ThreadContext.for_testing(recorder: @recorder, timeline_enabled: true) # We take a dummy sample so that the context for the main thread is created, as otherwise the GC profiling methods do # not create it (because we don't want to do memory allocations in the middle of GC) diff --git a/benchmarks/profiler_sample_loop_v2.rb b/benchmarks/profiler_sample_loop_v2.rb index b5499aa55a1..5c3e9a50149 100644 --- a/benchmarks/profiler_sample_loop_v2.rb +++ b/benchmarks/profiler_sample_loop_v2.rb @@ -21,9 +21,7 @@ def create_profiler heap_sample_every: 1, timeline_enabled: false, ) - @collector = Datadog::Profiling::Collectors::ThreadContext.new( - recorder: @recorder, max_frames: 400, tracer: nil, endpoint_collection_enabled: false, timeline_enabled: false - ) + @collector = Datadog::Profiling::Collectors::ThreadContext.for_testing(recorder: @recorder) end def thread_with_very_deep_stack(depth: 500) diff --git a/benchmarks/profiler_sample_serialize.rb b/benchmarks/profiler_sample_serialize.rb index 1b02f1de623..0414868613c 100644 --- a/benchmarks/profiler_sample_serialize.rb +++ b/benchmarks/profiler_sample_serialize.rb @@ -27,9 +27,7 @@ def create_profiler heap_sample_every: 1, timeline_enabled: timeline_enabled, ) - @collector = Datadog::Profiling::Collectors::ThreadContext.new( - recorder: @recorder, max_frames: 400, tracer: nil, endpoint_collection_enabled: false, timeline_enabled: timeline_enabled - ) + @collector = Datadog::Profiling::Collectors::ThreadContext.for_testing(recorder: @recorder, timeline_enabled: timeline_enabled) end def run_benchmark diff --git a/lib/datadog/profiling/collectors/thread_context.rb b/lib/datadog/profiling/collectors/thread_context.rb index 3f5e1606662..a42b4c3c85f 100644 --- a/lib/datadog/profiling/collectors/thread_context.rb +++ b/lib/datadog/profiling/collectors/thread_context.rb @@ -34,6 +34,24 @@ def initialize( ) end + def self.for_testing( + recorder:, + max_frames: 400, + tracer: nil, + endpoint_collection_enabled: false, + timeline_enabled: false, + **options + ) + new( + recorder: recorder, + max_frames: max_frames, + tracer: tracer, + endpoint_collection_enabled: endpoint_collection_enabled, + timeline_enabled: timeline_enabled, + **options, + ) + end + def inspect # Compose Ruby's default inspect with our custom inspect for the native parts result = super() diff --git a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb index 4f4f2ac8391..66ab214f190 100644 --- a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb +++ b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb @@ -909,15 +909,7 @@ describe "#reset_after_fork" do subject(:reset_after_fork) { cpu_and_wall_time_worker.reset_after_fork } - let(:thread_context_collector) do - Datadog::Profiling::Collectors::ThreadContext.new( - recorder: recorder, - max_frames: 400, - tracer: nil, - endpoint_collection_enabled: endpoint_collection_enabled, - timeline_enabled: timeline_enabled, - ) - end + let(:thread_context_collector) { build_thread_context_collector(recorder) } let(:options) { {thread_context_collector: thread_context_collector} } before do @@ -1261,10 +1253,8 @@ def build_another_instance end def build_thread_context_collector(recorder) - Datadog::Profiling::Collectors::ThreadContext.new( + Datadog::Profiling::Collectors::ThreadContext.for_testing( recorder: recorder, - max_frames: 400, - tracer: nil, endpoint_collection_enabled: endpoint_collection_enabled, timeline_enabled: timeline_enabled, ) From 524e9d1a5f5834872f275a1cb6349f19ddc23153 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 13 Sep 2024 10:55:19 +0100 Subject: [PATCH 28/42] Make `waiting_for_gvl_threshold_ns` configurable instead of being hardcoded This setting is going to be the main overhead lever for the Waiting for GVL feature. Having it configurable will allow us to play with it and better find good defaults. --- .../collectors_cpu_and_wall_time_worker.c | 6 +++ .../collectors_thread_context.c | 29 +++++++---- .../profiling/collectors/thread_context.rb | 4 ++ lib/datadog/profiling/component.rb | 1 + .../profiling/collectors/thread_context.rbs | 2 + .../collectors/thread_context_spec.rb | 49 +++++++++++-------- spec/datadog/profiling/component_spec.rb | 1 + 7 files changed, 63 insertions(+), 29 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index b745b3ac1bc..a1af1f929bd 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -1308,6 +1308,12 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { if (event_id == RUBY_INTERNAL_THREAD_EVENT_READY) { /* waiting for gvl */ thread_context_collector_on_gvl_waiting(target_thread); } else if (event_id == RUBY_INTERNAL_THREAD_EVENT_RESUMED) { /* running/runnable */ + // Interesting note: A RUBY_INTERNAL_THREAD_EVENT_RESUMED is guaranteed to be called with the GVL being acquired. + // (And... I think target_thread will be == rb_thread_current()?) + // But we're not sure if we're on the main Ractor yet. The thread context collector actually can actually help here: + // it tags threads it's tracking, so if a thread is tagged then by definition we know that thread belongs to the main + // Ractor. Thus, if we really really wanted to access the state, we could do it after making sure we're on the correct Ractor. + bool should_sample = thread_context_collector_on_gvl_running(target_thread); if (should_sample) { diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 2b98bd1d510..0a5f4533026 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -96,6 +96,13 @@ static ID at_datadog_trace_id; // id of :@datadog_trace in Ruby static rb_internal_thread_specific_key_t per_thread_gvl_waiting_timestamp_key; #endif +// This is used by `thread_context_collector_on_gvl_running`. Because when that method gets called we're not sure if +// it's safe to access the state of the thread context collector, we store this setting as a global value. This does +// mean this setting is shared among all thread context collectors, and it's "last writer wins". +// In production this these should not be a problem: there should only be one profiler, which is the last one created, +// and that can be running. +static uint32_t global_waiting_for_gvl_threshold_ns = MILLIS_AS_NS(10); + // Contains state for a single ThreadContext instance struct thread_context_collector_state { // Note: Places in this file that usually need to be changed when this struct is changed are tagged with @@ -187,6 +194,7 @@ static VALUE _native_initialize( VALUE tracer_context_key, VALUE endpoint_collection_enabled, VALUE timeline_enabled, + VALUE waiting_for_gvl_threshold_ns, VALUE allocation_type_enabled ); static VALUE _native_sample(VALUE self, VALUE collector_instance, VALUE profiler_overhead_stack_thread); @@ -258,7 +266,7 @@ static bool handle_gvl_waiting( ); static VALUE _native_on_gvl_waiting(DDTRACE_UNUSED VALUE self, VALUE thread); static VALUE _native_gvl_waiting_at_for(DDTRACE_UNUSED VALUE self, VALUE thread); -static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread, VALUE waiting_for_gvl_threshold_ns); +static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread); static VALUE _native_sample_after_gvl_running(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread); static VALUE _native_apply_delta_to_cpu_time_at_previous_sample_ns(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread, VALUE delta_ns); @@ -278,7 +286,7 @@ void collectors_thread_context_init(VALUE profiling_module) { // https://bugs.ruby-lang.org/issues/18007 for a discussion around this. rb_define_alloc_func(collectors_thread_context_class, _native_new); - rb_define_singleton_method(collectors_thread_context_class, "_native_initialize", _native_initialize, 7); + rb_define_singleton_method(collectors_thread_context_class, "_native_initialize", _native_initialize, 8); rb_define_singleton_method(collectors_thread_context_class, "_native_inspect", _native_inspect, 1); rb_define_singleton_method(collectors_thread_context_class, "_native_reset_after_fork", _native_reset_after_fork, 1); rb_define_singleton_method(testing_module, "_native_sample", _native_sample, 2); @@ -295,7 +303,7 @@ void collectors_thread_context_init(VALUE profiling_module) { #ifndef NO_GVL_INSTRUMENTATION rb_define_singleton_method(testing_module, "_native_on_gvl_waiting", _native_on_gvl_waiting, 1); rb_define_singleton_method(testing_module, "_native_gvl_waiting_at_for", _native_gvl_waiting_at_for, 1); - rb_define_singleton_method(testing_module, "_native_on_gvl_running", _native_on_gvl_running, 2); + rb_define_singleton_method(testing_module, "_native_on_gvl_running", _native_on_gvl_running, 1); rb_define_singleton_method(testing_module, "_native_sample_after_gvl_running", _native_sample_after_gvl_running, 2); rb_define_singleton_method(testing_module, "_native_apply_delta_to_cpu_time_at_previous_sample_ns", _native_apply_delta_to_cpu_time_at_previous_sample_ns, 3); #endif @@ -421,10 +429,12 @@ static VALUE _native_initialize( VALUE tracer_context_key, VALUE endpoint_collection_enabled, VALUE timeline_enabled, + VALUE waiting_for_gvl_threshold_ns, VALUE allocation_type_enabled ) { ENFORCE_BOOLEAN(endpoint_collection_enabled); ENFORCE_BOOLEAN(timeline_enabled); + ENFORCE_TYPE(waiting_for_gvl_threshold_ns, T_FIXNUM); ENFORCE_BOOLEAN(allocation_type_enabled); struct thread_context_collector_state *state; @@ -439,6 +449,8 @@ static VALUE _native_initialize( state->timeline_enabled = (timeline_enabled == Qtrue); state->allocation_type_enabled = (allocation_type_enabled == Qtrue); + global_waiting_for_gvl_threshold_ns = NUM2UINT(waiting_for_gvl_threshold_ns); + if (RTEST(tracer_context_key)) { ENFORCE_TYPE(tracer_context_key, T_SYMBOL); // Note about rb_to_id and dynamic symbols: calling `rb_to_id` prevents symbols from ever being garbage collected. @@ -1041,6 +1053,7 @@ static VALUE _native_inspect(DDTRACE_UNUSED VALUE _self, VALUE collector_instanc rb_str_concat(result, rb_sprintf(" main_thread=%"PRIsVALUE, state->main_thread)); rb_str_concat(result, rb_sprintf(" gc_tracking=%"PRIsVALUE, gc_tracking_as_ruby_hash(state))); rb_str_concat(result, rb_sprintf(" otel_current_span_key=%"PRIsVALUE, state->otel_current_span_key)); + rb_str_concat(result, rb_sprintf(" global_waiting_for_gvl_threshold_ns=%u", global_waiting_for_gvl_threshold_ns)); return result; } @@ -1563,8 +1576,6 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) current_monotonic_wall_time_ns); } - #define WAITING_FOR_GVL_THRESHOLD_NS MILLIS_AS_NS(10) - // This function can get called from outside the GVL and even on non-main Ractors __attribute__((warn_unused_result)) bool thread_context_collector_on_gvl_running_with_threshold(VALUE thread, uint32_t waiting_for_gvl_threshold_ns) { @@ -1595,7 +1606,7 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self __attribute__((warn_unused_result)) bool thread_context_collector_on_gvl_running(VALUE thread) { - return thread_context_collector_on_gvl_running_with_threshold(thread, WAITING_FOR_GVL_THRESHOLD_NS); + return thread_context_collector_on_gvl_running_with_threshold(thread, global_waiting_for_gvl_threshold_ns); } // Why does this method need to exist? @@ -1608,7 +1619,7 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self // returning true is the accuracy of the timing and stack for the Waiting for GVL to end. // // Timing: - // Because we currently only record when the Waiting for GVL started and not when the Waiting for GVL ended, + // Because we currently only record the timestamp when the Waiting for GVL started and not when the Waiting for GVL ended, // we rely on pushing a sample as soon as possible when the Waiting for GVL ends so that the timestamp of the sample // is close to the timestamp of finish the Waiting for GVL. // @@ -1777,10 +1788,10 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self return LONG2NUM(gvl_waiting_at); } - static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread, VALUE waiting_for_gvl_threshold_ns) { + static VALUE _native_on_gvl_running(DDTRACE_UNUSED VALUE self, VALUE thread) { ENFORCE_THREAD(thread); - return thread_context_collector_on_gvl_running_with_threshold(thread, NUM2UINT(waiting_for_gvl_threshold_ns)) ? Qtrue : Qfalse; + return thread_context_collector_on_gvl_running(thread) ? Qtrue : Qfalse; } static VALUE _native_sample_after_gvl_running(DDTRACE_UNUSED VALUE self, VALUE collector_instance, VALUE thread) { diff --git a/lib/datadog/profiling/collectors/thread_context.rb b/lib/datadog/profiling/collectors/thread_context.rb index a42b4c3c85f..c142704d862 100644 --- a/lib/datadog/profiling/collectors/thread_context.rb +++ b/lib/datadog/profiling/collectors/thread_context.rb @@ -20,6 +20,7 @@ def initialize( tracer:, endpoint_collection_enabled:, timeline_enabled:, + waiting_for_gvl_threshold_ns:, allocation_type_enabled: true ) tracer_context_key = safely_extract_context_key_from(tracer) @@ -30,6 +31,7 @@ def initialize( tracer_context_key, endpoint_collection_enabled, timeline_enabled, + waiting_for_gvl_threshold_ns, allocation_type_enabled, ) end @@ -40,6 +42,7 @@ def self.for_testing( tracer: nil, endpoint_collection_enabled: false, timeline_enabled: false, + waiting_for_gvl_threshold_ns: 10_000_000, **options ) new( @@ -48,6 +51,7 @@ def self.for_testing( tracer: tracer, endpoint_collection_enabled: endpoint_collection_enabled, timeline_enabled: timeline_enabled, + waiting_for_gvl_threshold_ns: waiting_for_gvl_threshold_ns, **options, ) end diff --git a/lib/datadog/profiling/component.rb b/lib/datadog/profiling/component.rb index 5f2c914a07c..9202564ecc0 100644 --- a/lib/datadog/profiling/component.rb +++ b/lib/datadog/profiling/component.rb @@ -89,6 +89,7 @@ def self.build_profiler_component(settings:, agent_settings:, optional_tracer:) tracer: optional_tracer, endpoint_collection_enabled: settings.profiling.advanced.endpoint.collection.enabled, timeline_enabled: timeline_enabled, + waiting_for_gvl_threshold_ns: 10_000_000, # TODO: Make this configurable, from the settings ) end diff --git a/sig/datadog/profiling/collectors/thread_context.rbs b/sig/datadog/profiling/collectors/thread_context.rbs index 888fdc9dda0..8ba16da0dbd 100644 --- a/sig/datadog/profiling/collectors/thread_context.rbs +++ b/sig/datadog/profiling/collectors/thread_context.rbs @@ -8,6 +8,7 @@ module Datadog tracer: Datadog::Tracing::Tracer?, endpoint_collection_enabled: bool, timeline_enabled: bool, + waiting_for_gvl_threshold_ns: ::Integer, ?allocation_type_enabled: bool, ) -> void @@ -18,6 +19,7 @@ module Datadog ::Symbol? tracer_context_key, bool endpoint_collection_enabled, bool timeline_enabled, + ::Integer waiting_for_gvl_threshold_ns, bool allocation_type_enabled, ) -> void diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 5c9fb81fbdf..430bebb8a48 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -44,6 +44,7 @@ # This mirrors the use of INTPTR_MAX for GVL_WAITING_ENABLED_EMPTY in the native code; it may need adjusting if we ever # want to support more platforms let(:gvl_waiting_enabled_empty_magic_value) { 2**63 - 1 } + let(:waiting_for_gvl_threshold_ns) { 222_333_444 } subject(:cpu_and_wall_time_collector) do described_class.new( @@ -52,6 +53,7 @@ tracer: tracer, endpoint_collection_enabled: endpoint_collection_enabled, timeline_enabled: timeline_enabled, + waiting_for_gvl_threshold_ns: waiting_for_gvl_threshold_ns, allocation_type_enabled: allocation_type_enabled, ) end @@ -95,8 +97,8 @@ def gvl_waiting_at_for(thread) described_class::Testing._native_gvl_waiting_at_for(thread) end - def on_gvl_running(thread, waiting_for_gvl_threshold_ns) - described_class::Testing._native_on_gvl_running(thread, waiting_for_gvl_threshold_ns) + def on_gvl_running(thread) + described_class::Testing._native_on_gvl_running(thread) end def sample_after_gvl_running(thread) @@ -134,6 +136,13 @@ def another_way_of_calling_sample(profiler_overhead_stack_thread: Thread.current sample(profiler_overhead_stack_thread: profiler_overhead_stack_thread) end + describe ".new" do + it "sets the waiting_for_gvl_threshold_ns to the provided value" do + # This is a bit ugly but it saves us from having to introduce yet another way to poke at the native state + expect(cpu_and_wall_time_collector.inspect).to include("global_waiting_for_gvl_threshold_ns=222333444") + end + end + describe "#sample" do it "samples all threads" do all_threads = Thread.list @@ -897,12 +906,10 @@ def sample_and_check(expected_state:) end context "when thread is ready to run again" do - before do - on_gvl_running(t1, threshold) - end + before { on_gvl_running(t1) } context "when Waiting for GVL duration >= the threshold" do - let(:threshold) { 0 } + let(:waiting_for_gvl_threshold_ns) { 0 } it "records a last Waiting for GVL sample" do sample_and_check(expected_state: "waiting for gvl") @@ -943,7 +950,7 @@ def sample_and_check(expected_state:) end context "when Waiting for GVL duration < the threshold" do - let(:threshold) { 1_000_000_000 } + let(:waiting_for_gvl_threshold_ns) { 1_000_000_000 } it "records a regular sample" do expect(gvl_waiting_at_for(t1)).to eq gvl_waiting_enabled_empty_magic_value @@ -1489,7 +1496,7 @@ def sample_and_check(expected_state:) context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do - on_gvl_running(t1, 0) + on_gvl_running(t1) expect(gvl_waiting_at_for(t1)).to be 0 end @@ -1502,11 +1509,11 @@ def sample_and_check(expected_state:) end it do - expect { on_gvl_running(t1, 0) }.to_not(change { gvl_waiting_at_for(t1) }) + expect { on_gvl_running(t1) }.to_not(change { gvl_waiting_at_for(t1) }) end it "does not flag that a sample is needed" do - expect(on_gvl_running(t1, 0)).to be false + expect(on_gvl_running(t1)).to be false end end @@ -1519,28 +1526,28 @@ def sample_and_check(expected_state:) end context "when Waiting for GVL duration >= the threshold" do - let(:threshold) { 0 } + let(:waiting_for_gvl_threshold_ns) { 0 } it "flips the value of gvl_waiting_at to negative" do - expect { on_gvl_running(t1, threshold) } + expect { on_gvl_running(t1) } .to change { gvl_waiting_at_for(t1) } .from(@gvl_waiting_at) .to(-@gvl_waiting_at) end it "flags that a sample is needed" do - expect(on_gvl_running(t1, threshold)).to be true + expect(on_gvl_running(t1)).to be true end context "when called several times in a row" do - before { on_gvl_running(t1, threshold) } + before { on_gvl_running(t1) } it "flags that a sample is needed" do - expect(on_gvl_running(t1, threshold)).to be true + expect(on_gvl_running(t1)).to be true end it "keeps the value of gvl_waiting_at as negative" do - on_gvl_running(t1, threshold) + on_gvl_running(t1) expect(gvl_waiting_at_for(t1)).to be(-@gvl_waiting_at) end @@ -1548,17 +1555,17 @@ def sample_and_check(expected_state:) end context "when Waiting for GVL duration < the threshold" do - let(:threshold) { 1_000_000_000 } + let(:waiting_for_gvl_threshold_ns) { 1_000_000_000 } it "resets the value of gvl_waiting_at back to GVL_WAITING_ENABLED_EMPTY" do - expect { on_gvl_running(t1, threshold) } + expect { on_gvl_running(t1) } .to change { gvl_waiting_at_for(t1) } .from(@gvl_waiting_at) .to(gvl_waiting_enabled_empty_magic_value) end it "flags that a sample is not needed" do - expect(on_gvl_running(t1, threshold)).to be false + expect(on_gvl_running(t1)).to be false end end end @@ -1593,13 +1600,15 @@ def sample_and_check(expected_state:) # # Thus, I chose to not repeat the extensive Waiting for GVL asserts we already have in #sample, and do a smaller pass. context "when thread is at the end of a Waiting for GVL period" do + let(:waiting_for_gvl_threshold_ns) { 0 } + before do sample # trigger context creation on_gvl_waiting(t1) sample if record_start - on_gvl_running(t1, 0) + on_gvl_running(t1) samples_from_pprof(recorder.serialize!) # flush samples expect(gvl_waiting_at_for(t1)).to be < 0 diff --git a/spec/datadog/profiling/component_spec.rb b/spec/datadog/profiling/component_spec.rb index c993d7b874d..0a8e1a38b02 100644 --- a/spec/datadog/profiling/component_spec.rb +++ b/spec/datadog/profiling/component_spec.rb @@ -77,6 +77,7 @@ tracer: tracer, endpoint_collection_enabled: :endpoint_collection_enabled_config, timeline_enabled: :timeline_enabled_config, + waiting_for_gvl_threshold_ns: 10_000_000, # TODO: Make this configurable, from the settings ) build_profiler_component From 0c7c1b50117f313778359a61f95412f7af8af2bb Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 13 Sep 2024 11:28:58 +0100 Subject: [PATCH 29/42] Convert `CpuAndWallTimeWorker.new` to use keyword arguments This method has way too many positional arguments, let's try to avoid this footgun by using keyword arguments instead. --- .../collectors_cpu_and_wall_time_worker.c | 48 ++++++++----------- .../collectors/cpu_and_wall_time_worker.rb | 22 ++++----- .../collectors/cpu_and_wall_time_worker.rbs | 22 ++++----- 3 files changed, 41 insertions(+), 51 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index a1af1f929bd..053878845b4 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -180,20 +180,7 @@ struct cpu_and_wall_time_worker_state { }; static VALUE _native_new(VALUE klass); -static VALUE _native_initialize( - DDTRACE_UNUSED VALUE _self, - VALUE self_instance, - VALUE thread_context_collector_instance, - VALUE gc_profiling_enabled, - VALUE idle_sampling_helper_instance, - VALUE no_signals_workaround_enabled, - VALUE dynamic_sampling_rate_enabled, - VALUE dynamic_sampling_rate_overhead_target_percentage, - VALUE allocation_profiling_enabled, - VALUE allocation_counting_enabled, - VALUE gvl_profiling_enabled, - VALUE skip_idle_samples_for_testing -); +static VALUE _native_initialize(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self); static void cpu_and_wall_time_worker_typed_data_mark(void *state_ptr); static VALUE _native_sampling_loop(VALUE self, VALUE instance); static VALUE _native_stop(DDTRACE_UNUSED VALUE _self, VALUE self_instance, VALUE worker_thread); @@ -312,7 +299,7 @@ void collectors_cpu_and_wall_time_worker_init(VALUE profiling_module) { // https://bugs.ruby-lang.org/issues/18007 for a discussion around this. rb_define_alloc_func(collectors_cpu_and_wall_time_worker_class, _native_new); - rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_initialize", _native_initialize, 11); + rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_initialize", _native_initialize, -1); rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_sampling_loop", _native_sampling_loop, 1); rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_stop", _native_stop, 2); rb_define_singleton_method(collectors_cpu_and_wall_time_worker_class, "_native_reset_after_fork", _native_reset_after_fork, 1); @@ -390,20 +377,23 @@ static VALUE _native_new(VALUE klass) { return state->self_instance = TypedData_Wrap_Struct(klass, &cpu_and_wall_time_worker_typed_data, state); } -static VALUE _native_initialize( - DDTRACE_UNUSED VALUE _self, - VALUE self_instance, - VALUE thread_context_collector_instance, - VALUE gc_profiling_enabled, - VALUE idle_sampling_helper_instance, - VALUE no_signals_workaround_enabled, - VALUE dynamic_sampling_rate_enabled, - VALUE dynamic_sampling_rate_overhead_target_percentage, - VALUE allocation_profiling_enabled, - VALUE allocation_counting_enabled, - VALUE gvl_profiling_enabled, - VALUE skip_idle_samples_for_testing -) { +static VALUE _native_initialize(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self) { + VALUE options; + rb_scan_args(argc, argv, "0:", &options); + if (options == Qnil) options = rb_hash_new(); + + VALUE self_instance = rb_hash_fetch(options, ID2SYM(rb_intern("self_instance"))); + VALUE thread_context_collector_instance = rb_hash_fetch(options, ID2SYM(rb_intern("thread_context_collector"))); + VALUE gc_profiling_enabled = rb_hash_fetch(options, ID2SYM(rb_intern("gc_profiling_enabled"))); + VALUE idle_sampling_helper_instance = rb_hash_fetch(options, ID2SYM(rb_intern("idle_sampling_helper"))); + VALUE no_signals_workaround_enabled = rb_hash_fetch(options, ID2SYM(rb_intern("no_signals_workaround_enabled"))); + VALUE dynamic_sampling_rate_enabled = rb_hash_fetch(options, ID2SYM(rb_intern("dynamic_sampling_rate_enabled"))); + VALUE dynamic_sampling_rate_overhead_target_percentage = rb_hash_fetch(options, ID2SYM(rb_intern("dynamic_sampling_rate_overhead_target_percentage"))); + VALUE allocation_profiling_enabled = rb_hash_fetch(options, ID2SYM(rb_intern("allocation_profiling_enabled"))); + VALUE allocation_counting_enabled = rb_hash_fetch(options, ID2SYM(rb_intern("allocation_counting_enabled"))); + VALUE gvl_profiling_enabled = rb_hash_fetch(options, ID2SYM(rb_intern("gvl_profiling_enabled"))); + VALUE skip_idle_samples_for_testing = rb_hash_fetch(options, ID2SYM(rb_intern("skip_idle_samples_for_testing"))); + ENFORCE_BOOLEAN(gc_profiling_enabled); ENFORCE_BOOLEAN(no_signals_workaround_enabled); ENFORCE_BOOLEAN(dynamic_sampling_rate_enabled); diff --git a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb index abaa2bbea70..418108fc061 100644 --- a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb +++ b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb @@ -37,17 +37,17 @@ def initialize( gvl_profiling_enabled = ENV["TESTING_GVL_PROFILING"] == "true" self.class._native_initialize( - self, - thread_context_collector, - gc_profiling_enabled, - idle_sampling_helper, - no_signals_workaround_enabled, - dynamic_sampling_rate_enabled, - dynamic_sampling_rate_overhead_target_percentage, - allocation_profiling_enabled, - allocation_counting_enabled, - gvl_profiling_enabled, - skip_idle_samples_for_testing, + self_instance: self, + thread_context_collector: thread_context_collector, + gc_profiling_enabled: gc_profiling_enabled, + idle_sampling_helper: idle_sampling_helper, + no_signals_workaround_enabled: no_signals_workaround_enabled, + dynamic_sampling_rate_enabled: dynamic_sampling_rate_enabled, + dynamic_sampling_rate_overhead_target_percentage: dynamic_sampling_rate_overhead_target_percentage, + allocation_profiling_enabled: allocation_profiling_enabled, + allocation_counting_enabled: allocation_counting_enabled, + gvl_profiling_enabled: gvl_profiling_enabled, + skip_idle_samples_for_testing: skip_idle_samples_for_testing, ) @worker_thread = nil @failure_exception = nil diff --git a/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs b/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs index 7e54f4eacd6..27ec01bef2c 100644 --- a/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs +++ b/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs @@ -20,17 +20,17 @@ module Datadog ) -> void def self._native_initialize: ( - CpuAndWallTimeWorker self_instance, - ThreadContext thread_context_collector, - bool gc_profiling_enabled, - IdleSamplingHelper idle_sampling_helper, - bool no_signals_workaround_enabled, - bool dynamic_sampling_rate_enabled, - Float dynamic_sampling_rate_overhead_target_percentage, - bool allocation_profiling_enabled, - bool allocation_counting_enabled, - bool gvl_profiling_enabled, - bool skip_idle_samples_for_testing, + self_instance: CpuAndWallTimeWorker, + thread_context_collector: ThreadContext, + gc_profiling_enabled: bool, + idle_sampling_helper: IdleSamplingHelper, + no_signals_workaround_enabled: bool, + dynamic_sampling_rate_enabled: bool, + dynamic_sampling_rate_overhead_target_percentage: Float, + allocation_profiling_enabled: bool, + allocation_counting_enabled: bool, + gvl_profiling_enabled: bool, + skip_idle_samples_for_testing: bool, ) -> true def start: (?on_failure_proc: ::Proc?) -> bool? From d05beb37eb092bea72c62a6375a50777d17716e6 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 13 Sep 2024 11:44:03 +0100 Subject: [PATCH 30/42] Expose `gvl_profiling_enabled` argument when initializing CpuAndWallTimeWorker --- lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb | 3 +-- lib/datadog/profiling/component.rb | 1 + sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs | 1 + .../profiling/collectors/cpu_and_wall_time_worker_spec.rb | 2 ++ spec/datadog/profiling/component_spec.rb | 1 + 5 files changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb index 418108fc061..83715c58ac7 100644 --- a/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb +++ b/lib/datadog/profiling/collectors/cpu_and_wall_time_worker.rb @@ -22,6 +22,7 @@ def initialize( dynamic_sampling_rate_overhead_target_percentage:, allocation_profiling_enabled:, allocation_counting_enabled:, + gvl_profiling_enabled:, # **NOTE**: This should only be used for testing; disabling the dynamic sampling rate will increase the # profiler overhead! dynamic_sampling_rate_enabled: true, @@ -34,8 +35,6 @@ def initialize( ) end - gvl_profiling_enabled = ENV["TESTING_GVL_PROFILING"] == "true" - self.class._native_initialize( self_instance: self, thread_context_collector: thread_context_collector, diff --git a/lib/datadog/profiling/component.rb b/lib/datadog/profiling/component.rb index 9202564ecc0..3d598622cc2 100644 --- a/lib/datadog/profiling/component.rb +++ b/lib/datadog/profiling/component.rb @@ -62,6 +62,7 @@ def self.build_profiler_component(settings:, agent_settings:, optional_tracer:) dynamic_sampling_rate_overhead_target_percentage: overhead_target_percentage, allocation_profiling_enabled: allocation_profiling_enabled, allocation_counting_enabled: settings.profiling.advanced.allocation_counting_enabled, + gvl_profiling_enabled: false, # TODO: Make this configurable, from the settings ) internal_metadata = { diff --git a/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs b/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs index 27ec01bef2c..5813dff08d5 100644 --- a/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs +++ b/sig/datadog/profiling/collectors/cpu_and_wall_time_worker.rbs @@ -16,6 +16,7 @@ module Datadog ?dynamic_sampling_rate_enabled: bool, allocation_profiling_enabled: bool, allocation_counting_enabled: bool, + gvl_profiling_enabled: bool, ?skip_idle_samples_for_testing: false, ) -> void diff --git a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb index 66ab214f190..79f6e04ef24 100644 --- a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb +++ b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb @@ -16,6 +16,7 @@ let(:timeline_enabled) { false } let(:options) { {} } let(:allocation_counting_enabled) { false } + let(:gvl_profiling_enabled) { false } let(:worker_settings) do { gc_profiling_enabled: gc_profiling_enabled, @@ -24,6 +25,7 @@ dynamic_sampling_rate_overhead_target_percentage: 2.0, allocation_profiling_enabled: allocation_profiling_enabled, allocation_counting_enabled: allocation_counting_enabled, + gvl_profiling_enabled: gvl_profiling_enabled, **options } end diff --git a/spec/datadog/profiling/component_spec.rb b/spec/datadog/profiling/component_spec.rb index 0a8e1a38b02..02c84194e49 100644 --- a/spec/datadog/profiling/component_spec.rb +++ b/spec/datadog/profiling/component_spec.rb @@ -99,6 +99,7 @@ dynamic_sampling_rate_overhead_target_percentage: :overhead_target_percentage_config, allocation_profiling_enabled: false, allocation_counting_enabled: :allocation_counting_enabled_config, + gvl_profiling_enabled: false, # TODO: Make this configurable, from the settings ) build_profiler_component From 67dc4e76d98d26d8240e68ea507da98eb00f4c59 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 13 Sep 2024 13:46:29 +0100 Subject: [PATCH 31/42] Add integration spec for GVL profiling behavior in CpuAndWallTimeWorker --- .../collectors_cpu_and_wall_time_worker.c | 9 +++ .../cpu_and_wall_time_worker_spec.rb | 65 ++++++++++++++++++- .../collectors/thread_context_spec.rb | 1 - spec/datadog/profiling/spec_helper.rb | 6 +- 4 files changed, 77 insertions(+), 4 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index 053878845b4..d2de40f905e 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -176,6 +176,10 @@ struct cpu_and_wall_time_worker_state { uint64_t allocation_sampling_time_ns_total; // How many times we saw allocations being done inside a sample unsigned int allocations_during_sample; + + // # GVL profiling stats + // How many times we triggered the after_gvl_running sampling + unsigned int after_gvl_running; } stats; }; @@ -1028,6 +1032,9 @@ static VALUE _native_stats(DDTRACE_UNUSED VALUE self, VALUE instance) { ID2SYM(rb_intern("allocation_sampling_time_ns_avg")), /* => */ RUBY_AVG_OR_NIL(state->stats.allocation_sampling_time_ns_total, state->stats.allocation_sampled), ID2SYM(rb_intern("allocation_sampler_snapshot")), /* => */ allocation_sampler_snapshot, ID2SYM(rb_intern("allocations_during_sample")), /* => */ state->allocation_profiling_enabled ? UINT2NUM(state->stats.allocations_during_sample) : Qnil, + + // GVL profiling stats + ID2SYM(rb_intern("after_gvl_running")), /* => */ UINT2NUM(state->stats.after_gvl_running), }; for (long unsigned int i = 0; i < VALUE_COUNT(arguments); i += 2) rb_hash_aset(stats_as_hash, arguments[i], arguments[i+1]); return stats_as_hash; @@ -1326,6 +1333,8 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { safely_call(thread_context_collector_sample_after_gvl_running, state->thread_context_collector_instance, state->self_instance); + state->stats.after_gvl_running++; + state->during_sample = false; } #endif diff --git a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb index 79f6e04ef24..c82dd82d570 100644 --- a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb +++ b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb @@ -325,7 +325,7 @@ end end - context "when main thread is sleeping but a background thread is working" do + context "when main thread is sleeping but a background thread is working", :memcheck_valgrind_skip do let(:ready_queue) { Queue.new } let(:background_thread) do Thread.new do @@ -340,7 +340,7 @@ background_thread.join end - it "is able to sample even when the main thread is sleeping", :memcheck_valgrind_skip do + it "is able to sample even when the main thread is sleeping" do background_thread ready_queue.pop @@ -372,6 +372,66 @@ expect(sample_count).to be >= 5, "sample_count: #{sample_count}, stats: #{stats}" expect(trigger_sample_attempts).to be >= sample_count end + + context "when GVL profiling is enabled" do + before do + if min_ruby_for_gvl_profiling > RUBY_VERSION + skip "GVL profiling is is only supported on Ruby >= #{min_ruby_for_gvl_profiling}" + end + end + + let(:gvl_profiling_enabled) { true } + + let(:timeline_enabled) { true } + let(:ready_queue_2) { Queue.new } + let(:background_thread_affected_by_gvl_contention) do + Thread.new do + ready_queue_2 << true + loop { Thread.pass } + end + end + + after do + background_thread_affected_by_gvl_contention.kill + background_thread_affected_by_gvl_contention.join + end + + it "records Waiting for GVL samples" do + background_thread_affected_by_gvl_contention + ready_queue_2.pop + + start + wait_until_running + + background_thread + ready_queue.pop + + sleep 0.2 + + cpu_and_wall_time_worker.stop + + background_thread.kill + background_thread_affected_by_gvl_contention.kill + + samples = samples_for_thread( + samples_from_pprof_without_gc_and_overhead(recorder.serialize!), + background_thread_affected_by_gvl_contention + ) + + waiting_for_gvl_samples = samples.select { |sample| sample.labels[:state] == "waiting for gvl" } + total_time = samples.sum { |sample| sample.values.fetch(:"wall-time") } + waiting_for_gvl_time = waiting_for_gvl_samples.sum { |sample| sample.values.fetch(:"wall-time") } + + expect(waiting_for_gvl_samples.size).to be > 0 + + # The background thread should spend almost all of its time waiting to run (since when it gets to run + # it just passes and starts waiting) + expect(waiting_for_gvl_time).to be < total_time + expect(waiting_for_gvl_time).to be_within(5).percent_of(total_time) + + expect(cpu_and_wall_time_worker.stats.fetch(:after_gvl_running)).to be > 0 + end + end end context "when all threads are sleeping (no thread holds the Global VM Lock)" do @@ -974,6 +1034,7 @@ allocation_sampling_time_ns_avg: nil, allocation_sampler_snapshot: nil, allocations_during_sample: nil, + after_gvl_running: 0, } ) end diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 430bebb8a48..dc0447fe7b6 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -40,7 +40,6 @@ let(:endpoint_collection_enabled) { true } let(:timeline_enabled) { false } let(:allocation_type_enabled) { true } - let(:min_ruby_for_gvl_profiling) { "3.3." } # This mirrors the use of INTPTR_MAX for GVL_WAITING_ENABLED_EMPTY in the native code; it may need adjusting if we ever # want to support more platforms let(:gvl_waiting_enabled_empty_magic_value) { 2**63 - 1 } diff --git a/spec/datadog/profiling/spec_helper.rb b/spec/datadog/profiling/spec_helper.rb index 3eb5e4cecda..92d3fa36ae5 100644 --- a/spec/datadog/profiling/spec_helper.rb +++ b/spec/datadog/profiling/spec_helper.rb @@ -55,7 +55,7 @@ def samples_from_pprof(pprof_data) sample.label.map do |it| key = string_table[it.key].to_sym [key, ((it.num == 0) ? string_table[it.str] : ProfileHelpers.maybe_fix_label_range(key, it.num))] - end.to_h, + end.sort.to_h, ).freeze end end @@ -121,6 +121,10 @@ def self.maybe_fix_label_range(key, value) value end end + + def min_ruby_for_gvl_profiling + "3.3." + end end RSpec.configure do |config| From 491d5dcaf77d4fa25daf45be5f6afaad37dfca15 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 13 Sep 2024 14:08:01 +0100 Subject: [PATCH 32/42] Add testing for enabling the GVL profiling hook + a small refactor for skipping GVL profiling specs on legacy Rubies --- .../collectors_cpu_and_wall_time_worker.c | 13 +++++ .../cpu_and_wall_time_worker_spec.rb | 52 +++++++++++++++++-- .../collectors/thread_context_spec.rb | 14 ++--- spec/datadog/profiling/spec_helper.rb | 4 +- 4 files changed, 69 insertions(+), 14 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index d2de40f905e..9296fb7e753 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -230,6 +230,7 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self); static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused); #endif static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused); +static VALUE _native_gvl_profiling_hook_active(DDTRACE_UNUSED VALUE self, VALUE instance); // We're using `on_newobj_event` function with `rb_add_event_hook2`, which requires in its public signature a function // with signature `rb_event_hook_func_t` which doesn't match `on_newobj_event`. @@ -325,6 +326,7 @@ void collectors_cpu_and_wall_time_worker_init(VALUE profiling_module) { rb_define_singleton_method(testing_module, "_native_is_sigprof_blocked_in_current_thread", _native_is_sigprof_blocked_in_current_thread, 0); rb_define_singleton_method(testing_module, "_native_with_blocked_sigprof", _native_with_blocked_sigprof, 0); rb_define_singleton_method(testing_module, "_native_delayed_error", _native_delayed_error, 2); + rb_define_singleton_method(testing_module, "_native_gvl_profiling_hook_active", _native_gvl_profiling_hook_active, 1); } // This structure is used to define a Ruby object that stores a pointer to a struct cpu_and_wall_time_worker_state @@ -1338,3 +1340,14 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { state->during_sample = false; } #endif + +static VALUE _native_gvl_profiling_hook_active(DDTRACE_UNUSED VALUE self, VALUE instance) { + #ifndef NO_GVL_INSTRUMENTATION + struct cpu_and_wall_time_worker_state *state; + TypedData_Get_Struct(instance, struct cpu_and_wall_time_worker_state, &cpu_and_wall_time_worker_typed_data, state); + + return state->gvl_profiling_hook != NULL ? Qtrue : Qfalse; + #else + return Qfalse; + #endif +} diff --git a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb index c82dd82d570..4f2c073d655 100644 --- a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb +++ b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb @@ -136,6 +136,28 @@ end end + context "when gvl_profiling_enabled is true" do + before { skip_if_gvl_profiling_not_supported(self) } + + let(:gvl_profiling_enabled) { true } + + it "enables the gvl profiling hook" do + start + + expect(described_class::Testing._native_gvl_profiling_hook_active(cpu_and_wall_time_worker)).to be true + end + end + + context "when gvl_profiling_enabled is false" do + let(:gvl_profiling_enabled) { false } + + it "does not enable the gvl profiling hook" do + start + + expect(described_class::Testing._native_gvl_profiling_hook_active(cpu_and_wall_time_worker)).to be false + end + end + context "when a previous signal handler existed" do before do described_class::Testing._native_install_testing_signal_handler @@ -374,11 +396,7 @@ end context "when GVL profiling is enabled" do - before do - if min_ruby_for_gvl_profiling > RUBY_VERSION - skip "GVL profiling is is only supported on Ruby >= #{min_ruby_for_gvl_profiling}" - end - end + before { skip_if_gvl_profiling_not_supported(self) } let(:gvl_profiling_enabled) { true } @@ -947,6 +965,18 @@ # come from us -- it's the default message for an unhandled SIGPROF. Pretty confusing UNIX/POSIX behavior...) Process.kill("SIGPROF", Process.pid) end + + context "when GVL profiling is enabled" do + before { skip_if_gvl_profiling_not_supported(self) } + + let(:gvl_profiling_enabled) { true } + + it "disables the GVL profiling hook" do + expect { stop } + .to change { described_class::Testing._native_gvl_profiling_hook_active(cpu_and_wall_time_worker) } + .from(true).to(false) + end + end end it "unblocks SIGPROF signal handling from the worker thread" do @@ -993,6 +1023,18 @@ .from(true).to(false) end + context "when gvl_profiling_enabled is true" do + before { skip_if_gvl_profiling_not_supported(self) } + + let(:gvl_profiling_enabled) { true } + + it "disables the gvl profiling hook" do + expect { reset_after_fork } + .to change { described_class::Testing._native_gvl_profiling_hook_active(cpu_and_wall_time_worker) } + .from(true).to(false) + end + end + it "resets the CpuAndWallTime collector only after disabling the tracepoint" do expect(thread_context_collector).to receive(:reset_after_fork) do expect(described_class::Testing._native_gc_tracepoint(cpu_and_wall_time_worker)).to_not be_enabled diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index dc0447fe7b6..9b81616500c 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -780,7 +780,7 @@ def self.otel_sdk_available? context "when thread starts Waiting for GVL" do before do - skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION + skip_if_gvl_profiling_not_supported(self) sample # trigger context creation samples_from_pprof(recorder.serialize!) # flush sample @@ -843,7 +843,7 @@ def self.otel_sdk_available? context "when thread is Waiting for GVL" do before do - skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION + skip_if_gvl_profiling_not_supported(self) sample # trigger context creation on_gvl_waiting(t1) @@ -1465,7 +1465,7 @@ def sample_and_check(expected_state:) end describe "#on_gvl_waiting" do - before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } + before { skip_if_gvl_profiling_not_supported(self) } context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do @@ -1491,7 +1491,7 @@ def sample_and_check(expected_state:) end describe "#on_gvl_running" do - before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } + before { skip_if_gvl_profiling_not_supported(self) } context "if thread has not been sampled before" do it "does not record anything in the internal_thread_specific value" do @@ -1571,7 +1571,7 @@ def sample_and_check(expected_state:) end describe "#sample_after_gvl_running" do - before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } + before { skip_if_gvl_profiling_not_supported(self) } let(:timeline_enabled) { true } @@ -1823,7 +1823,7 @@ def sample_and_check(expected_state:) describe ":gvl_waiting_at" do context "on supported Rubies" do - before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling > RUBY_VERSION } + before { skip_if_gvl_profiling_not_supported(self) } it "is initialized to GVL_WAITING_ENABLED_EMPTY (INTPTR_MAX)" do expect(per_thread_context.values).to all( @@ -1833,7 +1833,7 @@ def sample_and_check(expected_state:) end context "on legacy Rubies" do - before { skip "Behavior does not apply to current Ruby version" if min_ruby_for_gvl_profiling <= RUBY_VERSION } + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION >= "3.3." } it "is not set" do per_thread_context.each do |_thread, context| diff --git a/spec/datadog/profiling/spec_helper.rb b/spec/datadog/profiling/spec_helper.rb index 92d3fa36ae5..205000b7f32 100644 --- a/spec/datadog/profiling/spec_helper.rb +++ b/spec/datadog/profiling/spec_helper.rb @@ -122,8 +122,8 @@ def self.maybe_fix_label_range(key, value) end end - def min_ruby_for_gvl_profiling - "3.3." + def skip_if_gvl_profiling_not_supported(testcase) + testcase.skip "GVL profiling is only supported on Ruby >= 3.3" if RUBY_VERSION < "3.3." end end From 39a0d3d4dbc9b3655ea0dfbc21e4af41bdc2079e Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 11:31:32 +0100 Subject: [PATCH 33/42] Small set of cleanups and comment improvements after review --- .../collectors_cpu_and_wall_time_worker.c | 4 +-- .../collectors_thread_context.c | 36 ++++++++++--------- .../extconf.rb | 2 +- .../collectors/thread_context_spec.rb | 8 ++--- 4 files changed, 26 insertions(+), 24 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index 9296fb7e753..a04303f021d 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -228,8 +228,8 @@ static VALUE _native_hold_signals(DDTRACE_UNUSED VALUE self); static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self); #ifndef NO_GVL_INSTRUMENTATION static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused); -#endif static void after_gvl_running_from_postponed_job(DDTRACE_UNUSED void *_unused); +#endif static VALUE _native_gvl_profiling_hook_active(DDTRACE_UNUSED VALUE self, VALUE instance); // We're using `on_newobj_event` function with `rb_add_event_hook2`, which requires in its public signature a function @@ -1298,7 +1298,7 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { #ifndef NO_GVL_INSTRUMENTATION static void on_gvl_event(rb_event_flag_t event_id, const rb_internal_thread_event_data_t *event_data, DDTRACE_UNUSED void *_unused) { // Be very careful about touching the `state` here or doing anything at all: - // This function gets called even without the GVL, and even from background Ractors! + // This function gets called without the GVL, and potentially from background Ractors! // // In fact, the `target_thread` that this event is about may not even be the current thread. (So be careful with thread locals that // are not directly tied to the `target_thread` object and the like) diff --git a/ext/datadog_profiling_native_extension/collectors_thread_context.c b/ext/datadog_profiling_native_extension/collectors_thread_context.c index 0a5f4533026..a71aa29d0c2 100644 --- a/ext/datadog_profiling_native_extension/collectors_thread_context.c +++ b/ext/datadog_profiling_native_extension/collectors_thread_context.c @@ -98,9 +98,9 @@ static rb_internal_thread_specific_key_t per_thread_gvl_waiting_timestamp_key; // This is used by `thread_context_collector_on_gvl_running`. Because when that method gets called we're not sure if // it's safe to access the state of the thread context collector, we store this setting as a global value. This does -// mean this setting is shared among all thread context collectors, and it's "last writer wins". -// In production this these should not be a problem: there should only be one profiler, which is the last one created, -// and that can be running. +// mean this setting is shared among all thread context collectors, and thus it's "last writer wins". +// In production this should not be a problem: there should only be one profiler, which is the last one created, +// and that'll be the one that last wrote this setting. static uint32_t global_waiting_for_gvl_threshold_ns = MILLIS_AS_NS(10); // Contains state for a single ThreadContext instance @@ -1584,7 +1584,7 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self // Thread was not being profiled / not waiting on gvl if (gvl_waiting_at == 0 || gvl_waiting_at == GVL_WAITING_ENABLED_EMPTY) return false; - // @ivoanjo: I'm not sure if this can happen -- It means we should've sampled already but didn't + // @ivoanjo: I'm not sure if this can happen -- It means we should've sampled already but haven't gotten the chance yet? if (gvl_waiting_at < 0) return true; long waiting_for_gvl_duration_ns = monotonic_wall_time_now_ns(DO_NOT_RAISE_ON_FAILURE) - gvl_waiting_at; @@ -1592,12 +1592,12 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self bool should_sample = waiting_for_gvl_duration_ns >= waiting_for_gvl_threshold_ns; if (should_sample) { - // We flip the gvl_waiting_at to negative to mark that the thread is now running + // We flip the gvl_waiting_at to negative to mark that the thread is now running and no longer waiting intptr_t gvl_waiting_at_is_now_running = -gvl_waiting_at; rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) gvl_waiting_at_is_now_running); } else { - // We decided not to sample. Let's mark the thread back to the initial enabled but empty state + // We decided not to sample. Let's mark the thread back to the initial "enabled but empty" state rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); } @@ -1611,35 +1611,37 @@ static VALUE _native_sample_skipped_allocation_samples(DDTRACE_UNUSED VALUE self // Why does this method need to exist? // - // You may be surprised to see that if you never call this method, Waiting for GVL samples will still show up. - // This is because regular cpu/wall-time samples also use `update_metrics_and_sample` which will push those samples - // as needed. + // You may be surprised to see that if we never call this function (from cpu_and_wall_time_worker), Waiting for GVL + // samples will still show up. + // This is because regular cpu/wall-time samples also use `update_metrics_and_sample` which will do the right thing + // and push "Waiting for GVL" samples as needed. // // The reason this method needs to exist and be called very shortly after thread_context_collector_on_gvl_running - // returning true is the accuracy of the timing and stack for the Waiting for GVL to end. + // returning true is to ensure accuracy of both the timing and stack for the Waiting for GVL sample. // // Timing: // Because we currently only record the timestamp when the Waiting for GVL started and not when the Waiting for GVL ended, // we rely on pushing a sample as soon as possible when the Waiting for GVL ends so that the timestamp of the sample - // is close to the timestamp of finish the Waiting for GVL. + // actually matches when we stopped waiting. // // Stack: - // If the thread starts working without the end of the Waiting for GVL sample, then by the time that sample happens - // (via the regular cpu/wall-time samples mechanism), the stack can be be inaccurate. + // If the thread starts working without the end of the Waiting for GVL sample, then by the time the thread is sampled + // via the regular cpu/wall-time samples mechanism, the stack can be be inaccurate (e.g. does not correctly pinpoint + // where the waiting happened). // // Arguably, the last sample after Waiting for GVL ended (when gvl_waiting_at < 0) should always come from this method - // and not a regular cpu/wall-time sample BUT since all of these things are happening in parallel I suspect + // and not a regular cpu/wall-time sample BUT since all of these things are happening in parallel/concurrently I suspect // it's possible for a regular sample to kick in just before this one. // // --- // - // NOTE: In normal use, current_thread is expected to be == rb_thread_current(); using a different thread is only - // to make testing easier. + // NOTE: In normal use, current_thread is expected to be == rb_thread_current(); the `current_thread` parameter only + // exists to enable testing. VALUE thread_context_collector_sample_after_gvl_running_with_thread(VALUE self_instance, VALUE current_thread) { struct thread_context_collector_state *state; TypedData_Get_Struct(self_instance, struct thread_context_collector_state, &thread_context_collector_typed_data, state); - if (!state->timeline_enabled) rb_raise(rb_eRuntimeError, "gvl profiling requires timeline to be enabled"); + if (!state->timeline_enabled) rb_raise(rb_eRuntimeError, "GVL profiling requires timeline to be enabled"); struct per_thread_context *thread_context = get_or_create_context_for(current_thread, state); diff --git a/ext/datadog_profiling_native_extension/extconf.rb b/ext/datadog_profiling_native_extension/extconf.rb index 21b1b3dccb0..09ac833bd1d 100644 --- a/ext/datadog_profiling_native_extension/extconf.rb +++ b/ext/datadog_profiling_native_extension/extconf.rb @@ -132,7 +132,7 @@ def skip_building_extension!(reason) have_func "malloc_stats" # On older Rubies, there was no GVL instrumentation API and APIs created to support it -# TODO: We can probably support Ruby 3.2 as well here, but not for the first version +# TODO: We can probably support Ruby 3.2 as well here, but we haven't done that work yet $defs << "-DNO_GVL_INSTRUMENTATION" if RUBY_VERSION < "3.3" # On older Rubies, rb_postponed_job_preregister/rb_postponed_job_trigger did not exist diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 9b81616500c..424cc9d1265 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -848,7 +848,7 @@ def self.otel_sdk_available? sample # trigger context creation on_gvl_waiting(t1) sample # trigger creation of sample representing the period before Waiting for GVL - samples_from_pprof(recorder.serialize!) # flush previous samples + recorder.serialize! # flush previous samples end def sample_and_check(expected_state:) @@ -924,7 +924,7 @@ def sample_and_check(expected_state:) it "does not record a new Waiting for GVL sample afterwards" do sample # last Waiting for GVL sample - samples_from_pprof(recorder.serialize!) # flush previous samples + recorder.serialize! # flush previous samples 3.times { sample_and_check(expected_state: "sleeping") } end @@ -1597,7 +1597,7 @@ def sample_and_check(expected_state:) # See the big comment next to the definition of `thread_context_collector_sample_after_gvl_running_with_thread` # for why we need a separate `sample_after_gvl_running`. # - # Thus, I chose to not repeat the extensive Waiting for GVL asserts we already have in #sample, and do a smaller pass. + # Thus, I chose to not repeat the extensive Waiting for GVL specs we already have in #sample, and do a smaller pass. context "when thread is at the end of a Waiting for GVL period" do let(:waiting_for_gvl_threshold_ns) { 0 } @@ -1608,7 +1608,7 @@ def sample_and_check(expected_state:) sample if record_start on_gvl_running(t1) - samples_from_pprof(recorder.serialize!) # flush samples + recorder.serialize! # flush samples expect(gvl_waiting_at_for(t1)).to be < 0 end From ceda29eca8b3119f32bbf46ef568bfee55d04cb4 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 11:58:11 +0100 Subject: [PATCH 34/42] Introduce setting for enabling GVL profiling --- lib/datadog/core/configuration/settings.rb | 26 +++++++++ lib/datadog/profiling/component.rb | 18 +++++- .../core/configuration/settings_spec.rb | 50 ++++++++++++++++ spec/datadog/profiling/component_spec.rb | 57 +++++++++++++++++-- 4 files changed, 145 insertions(+), 6 deletions(-) diff --git a/lib/datadog/core/configuration/settings.rb b/lib/datadog/core/configuration/settings.rb index 800e880fb04..45835ddcdcf 100644 --- a/lib/datadog/core/configuration/settings.rb +++ b/lib/datadog/core/configuration/settings.rb @@ -460,6 +460,32 @@ def initialize(*_) end end end + + # Enables GVL profiling. This will show when threads are waiting for GVL in the timeline view. + # + # This is a preview feature and disabled by default. It requires Ruby 3.3+ although in the future we may + # be able to support Ruby 3.2 as well. + # + # @default `DD_PROFILING_PREVIEW_GVL_ENABLED` environment variable as a boolean, otherwise `false` + option :preview_gvl_enabled do |o| + o.type :bool + o.env 'DD_PROFILING_PREVIEW_GVL_ENABLED' + o.default false + end + + # Controls the smallest time period the profiler will report a thread waiting for the GVL. + # + # The default value was set to minimize overhead. Periods smaller than the set value will not be reported (e.g. + # the thread will be reported as whatever it was doing before it waited for the GVL). + # + # We do not recommend setting this to less than 1ms. Tweaking this value can increase application latency and + # memory use. + # + # @default 10_000_000 (10ms) + option :waiting_for_gvl_threshold_ns do |o| + o.type :int + o.default 10_000_000 + end end # @public_api diff --git a/lib/datadog/profiling/component.rb b/lib/datadog/profiling/component.rb index 3d598622cc2..d99d5d9e42a 100644 --- a/lib/datadog/profiling/component.rb +++ b/lib/datadog/profiling/component.rb @@ -62,7 +62,7 @@ def self.build_profiler_component(settings:, agent_settings:, optional_tracer:) dynamic_sampling_rate_overhead_target_percentage: overhead_target_percentage, allocation_profiling_enabled: allocation_profiling_enabled, allocation_counting_enabled: settings.profiling.advanced.allocation_counting_enabled, - gvl_profiling_enabled: false, # TODO: Make this configurable, from the settings + gvl_profiling_enabled: enable_gvl_profiling?(settings), ) internal_metadata = { @@ -90,7 +90,7 @@ def self.build_profiler_component(settings:, agent_settings:, optional_tracer:) tracer: optional_tracer, endpoint_collection_enabled: settings.profiling.advanced.endpoint.collection.enabled, timeline_enabled: timeline_enabled, - waiting_for_gvl_threshold_ns: 10_000_000, # TODO: Make this configurable, from the settings + waiting_for_gvl_threshold_ns: settings.profiling.advanced.waiting_for_gvl_threshold_ns, ) end @@ -441,6 +441,20 @@ def self.build_profiler_component(settings:, agent_settings:, optional_tracer:) settings.profiling.advanced.dir_interruption_workaround_enabled end + + private_class_method def self.enable_gvl_profiling?(settings) + if RUBY_VERSION < "3.3" + if settings.profiling.advanced.preview_gvl_enabled + Datadog.logger.warn("GVL profiling is currently not supported in Ruby < 3.3 and will not be enabled.") + end + + return false + end + + # GVL profiling only makes sense in the context of timeline. We could emit a warning here, but not sure how + # useful it is -- if a customer disables timeline, there's nowhere to look for GVL profiling anyway! + settings.profiling.advanced.timeline_enabled && settings.profiling.advanced.preview_gvl_enabled + end end end end diff --git a/spec/datadog/core/configuration/settings_spec.rb b/spec/datadog/core/configuration/settings_spec.rb index c6da174f948..a9c12188b95 100644 --- a/spec/datadog/core/configuration/settings_spec.rb +++ b/spec/datadog/core/configuration/settings_spec.rb @@ -883,6 +883,56 @@ .to(false) end end + + describe '#preview_gvl_enabled' do + subject(:preview_gvl_enabled) { settings.profiling.advanced.preview_gvl_enabled } + + context 'when DD_PROFILING_PREVIEW_GVL_ENABLED' do + around do |example| + ClimateControl.modify('DD_PROFILING_PREVIEW_GVL_ENABLED' => environment) do + example.run + end + end + + context 'is not defined' do + let(:environment) { nil } + + it { is_expected.to be false } + end + + [true, false].each do |value| + context "is defined as #{value}" do + let(:environment) { value.to_s } + + it { is_expected.to be value } + end + end + end + end + + describe '#preview_gvl_enabled=' do + it 'updates the #preview_gvl_enabled setting' do + expect { settings.profiling.advanced.preview_gvl_enabled = true } + .to change { settings.profiling.advanced.preview_gvl_enabled } + .from(false) + .to(true) + end + end + + describe '#waiting_for_gvl_threshold_ns' do + subject(:waiting_for_gvl_threshold_ns) { settings.profiling.advanced.waiting_for_gvl_threshold_ns } + + it { is_expected.to be 10_000_000 } + end + + describe '#waiting_for_gvl_threshold_ns=' do + it 'updates the #waiting_for_gvl_threshold_ns setting' do + expect { settings.profiling.advanced.waiting_for_gvl_threshold_ns = 123_000_000 } + .to change { settings.profiling.advanced.waiting_for_gvl_threshold_ns } + .from(10_000_000) + .to(123_000_000) + end + end end describe '#upload' do diff --git a/spec/datadog/profiling/component_spec.rb b/spec/datadog/profiling/component_spec.rb index 02c84194e49..26884eb5a5b 100644 --- a/spec/datadog/profiling/component_spec.rb +++ b/spec/datadog/profiling/component_spec.rb @@ -67,9 +67,10 @@ expect(settings.profiling.advanced).to receive(:max_frames).and_return(:max_frames_config) expect(settings.profiling.advanced) - .to receive(:timeline_enabled).and_return(:timeline_enabled_config) + .to receive(:timeline_enabled).at_least(:once).and_return(:timeline_enabled_config) expect(settings.profiling.advanced.endpoint.collection) .to receive(:enabled).and_return(:endpoint_collection_enabled_config) + expect(settings.profiling.advanced).to receive(:waiting_for_gvl_threshold_ns).and_return(:threshold_ns_config) expect(Datadog::Profiling::Collectors::ThreadContext).to receive(:new).with( recorder: dummy_stack_recorder, @@ -77,7 +78,7 @@ tracer: tracer, endpoint_collection_enabled: :endpoint_collection_enabled_config, timeline_enabled: :timeline_enabled_config, - waiting_for_gvl_threshold_ns: 10_000_000, # TODO: Make this configurable, from the settings + waiting_for_gvl_threshold_ns: :threshold_ns_config, ) build_profiler_component @@ -91,6 +92,7 @@ .with(:overhead_target_percentage_config).and_return(:overhead_target_percentage_config) expect(settings.profiling.advanced) .to receive(:allocation_counting_enabled).and_return(:allocation_counting_enabled_config) + expect(described_class).to receive(:enable_gvl_profiling?).and_return(:gvl_profiling_result) expect(Datadog::Profiling::Collectors::CpuAndWallTimeWorker).to receive(:new).with( gc_profiling_enabled: anything, @@ -99,7 +101,7 @@ dynamic_sampling_rate_overhead_target_percentage: :overhead_target_percentage_config, allocation_profiling_enabled: false, allocation_counting_enabled: :allocation_counting_enabled_config, - gvl_profiling_enabled: false, # TODO: Make this configurable, from the settings + gvl_profiling_enabled: :gvl_profiling_result, ) build_profiler_component @@ -416,7 +418,7 @@ allow(Datadog::Profiling::StackRecorder).to receive(:new) expect(described_class).to receive(:no_signals_workaround_enabled?).and_return(:no_signals_result) - expect(settings.profiling.advanced).to receive(:timeline_enabled).and_return(:timeline_result) + expect(settings.profiling.advanced).to receive(:timeline_enabled).at_least(:once).and_return(:timeline_result) expect(settings.profiling.advanced).to receive(:experimental_heap_sample_rate).and_return(456) expect(Datadog::Profiling::Exporter).to receive(:new).with( hash_including( @@ -588,6 +590,53 @@ end end end + + context "when GVL profiling is requested" do + before { settings.profiling.advanced.preview_gvl_enabled = true } + + context "on Ruby < 3.3" do + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION >= "3.3." } + + it "does not enable GVL profiling" do + expect(Datadog::Profiling::Collectors::CpuAndWallTimeWorker) + .to receive(:new).with(hash_including(gvl_profiling_enabled: false)) + + build_profiler_component + end + + it "logs a warning" do + expect(Datadog.logger).to receive(:warn).with(/GVL profiling is currently not supported/) + + build_profiler_component + end + end + + context "on Ruby >= 3.3" do + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION < "3.3." } + + context "when timeline is enabled" do + before { settings.profiling.advanced.timeline_enabled = true } + + it "enables GVL profiling" do + expect(Datadog::Profiling::Collectors::CpuAndWallTimeWorker) + .to receive(:new).with(hash_including(gvl_profiling_enabled: true)) + + build_profiler_component + end + end + + context "when timeline is disabled" do + before { settings.profiling.advanced.timeline_enabled = false } + + it "does not enable GVL profiling" do + expect(Datadog::Profiling::Collectors::CpuAndWallTimeWorker) + .to receive(:new).with(hash_including(gvl_profiling_enabled: false)) + + build_profiler_component + end + end + end + end end end From 678739974b05477a844691a675bcdd69ed9f0643 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 13:46:08 +0100 Subject: [PATCH 35/42] Update type signatures for profiling component class --- sig/datadog/profiling/component.rbs | 1 + 1 file changed, 1 insertion(+) diff --git a/sig/datadog/profiling/component.rbs b/sig/datadog/profiling/component.rbs index df04cea2959..227383e0de6 100644 --- a/sig/datadog/profiling/component.rbs +++ b/sig/datadog/profiling/component.rbs @@ -39,6 +39,7 @@ module Datadog def self.valid_overhead_target: (::Float overhead_target_percentage) -> ::Float def self.looks_like_mariadb?: ({ header_version: ::String? }, ::Gem::Version) -> bool def self.dir_interruption_workaround_enabled?: (untyped settings, bool no_signals_workaround_enabled) -> bool + def self.enable_gvl_profiling?: (untyped settings) -> bool end end end From 26914e1d39759d3a88fa57e0112d394997730103 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 13:46:33 +0100 Subject: [PATCH 36/42] Minor tweak to wording in warning --- lib/datadog/core/telemetry/logger.rb | 2 +- spec/datadog/core/telemetry/logger_spec.rb | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/datadog/core/telemetry/logger.rb b/lib/datadog/core/telemetry/logger.rb index c03320b354a..78cfdf65d19 100644 --- a/lib/datadog/core/telemetry/logger.rb +++ b/lib/datadog/core/telemetry/logger.rb @@ -39,7 +39,7 @@ def instance components.telemetry else Datadog.logger.warn( - 'Fail to send telemetry log before components initialization or within components lifecycle' + 'Failed to send telemetry before components initialization or within components lifecycle' ) nil end diff --git a/spec/datadog/core/telemetry/logger_spec.rb b/spec/datadog/core/telemetry/logger_spec.rb index 4446945016e..d4361fa7989 100644 --- a/spec/datadog/core/telemetry/logger_spec.rb +++ b/spec/datadog/core/telemetry/logger_spec.rb @@ -36,7 +36,7 @@ it do exception = StandardError.new allow(Datadog.send(:components)).to receive(:telemetry).and_return(nil) - expect(Datadog.logger).to receive(:warn).with(/Fail to send telemetry log/) + expect(Datadog.logger).to receive(:warn).with(/Failed to send telemetry/) expect do described_class.report(exception, level: :error, description: 'Oops...') @@ -60,7 +60,7 @@ context 'when there is no telemetry component configured' do it do allow(Datadog.send(:components)).to receive(:telemetry).and_return(nil) - expect(Datadog.logger).to receive(:warn).with(/Fail to send telemetry log/) + expect(Datadog.logger).to receive(:warn).with(/Failed to send telemetry/) expect { described_class.error('description') }.not_to raise_error end From bbebed3228f3986308958f5b91f5b6e75a78a1f9 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 14:44:34 +0100 Subject: [PATCH 37/42] Update ProfilingDevelopment doc with GVL profiling notes --- docs/ProfilingDevelopment.md | 152 +++++++++++++++++++++++++++++++++++ 1 file changed, 152 insertions(+) diff --git a/docs/ProfilingDevelopment.md b/docs/ProfilingDevelopment.md index 681e75417b9..7ea255f93a9 100644 --- a/docs/ProfilingDevelopment.md +++ b/docs/ProfilingDevelopment.md @@ -4,6 +4,8 @@ This file contains development notes specific to the continuous profiler. For a more practical view of getting started with development of `datadog`, see . +There's also a `NativeExtentionDesign.md` file in the `ext/datadog_profiling_native_extension` that contains further profiler implementation design notes. + ## Profiling components high-level view Some of the profiling components referenced below are implemented using C code. As much as possible, that C code is still @@ -140,3 +142,153 @@ available, from the tracer. Note that if a given trace executes too fast, it's possible that the profiler will not contain any samples for that specific trace. Nevertheless, the linking still works and is useful, as it allows users to explore what was going on their profile at that time, even if they can't filter down to the specific request. + +## Tracking of cpu-time and wall-time spent during garbage collection + +See comments at the top of `collectors_thread_context.c` for an explanation on how that feature is implemented. + +## How GVL profiling works + +Profiling the Ruby Global VM Lock (GVL) works by using the [GVL instrumentation API](https://github.com/ruby/ruby/pull/5500). + +This API currently only works on Ruby 3.2+, although there were a few changes and refinements on Ruby 3.3+ and as of this writing +(September 2024) we _only_ support Ruby 3.3+. + +These blog posts are good starting points to understand this API: + +* https://ivoanjo.me/blog/2022/07/17/tracing-ruby-global-vm-lock/ +* https://ivoanjo.me/blog/2023/02/11/ruby-unexpected-io-vs-cpu-unfairness/ +* https://ivoanjo.me/blog/2023/07/23/understanding-the-ruby-global-vm-lock-by-observing-it/ + +Below follow some notes on how it works. Note that it's possible we'll forget to update this documentation as the code +changes, so take the below info as a starting point to understanding how the feature is integrated, rather than an exact spec. + +### Getting VM callbacks in `CpuAndWallTimeWorker` + +From our side, the magic starts in the `CpuAndWallTimeWorker` class. When GVL profiling is enabled, we ask the VM to tell +us about two kinds of thread events: + +```c + if (state->gvl_profiling_enabled) { + state->gvl_profiling_hook = rb_internal_thread_add_event_hook( + on_gvl_event, + ( + // For now we're only asking for these events, even though there's more + // (e.g. check docs or gvl-tracing gem) + RUBY_INTERNAL_THREAD_EVENT_READY /* waiting for gvl */ | + RUBY_INTERNAL_THREAD_EVENT_RESUMED /* running/runnable */ + ), + NULL + ); + } +``` + +As the comments hint at: +* `RUBY_INTERNAL_THREAD_EVENT_READY` is emitted by the VM when a thread is ready to start running again. E.g. it's now +waiting for its turn to acquire the GVL. We call this thread "Waiting for GVL" in the profiler code, as well as in the Datadog UX +* `RUBY_INTERNAL_THREAD_EVENT_RESUMED` is emitted by the VM immediately after a thread has acquired the GVL. It's so +immediately after that (looking at the VM code) it may not even have done all the cleanup needed after acquisition for the +thread to start running. + +Once one of those events happen, Ruby will tell us by calling our `on_gvl_event` function +(still in the `CpuAndWallTimeWorker`). + +Both events above are (as far as I know) emitted by the thread they are representing. But, we need to be very careful +about running code in `on_gvl_event` to handle these events: + +* `RUBY_INTERNAL_THREAD_EVENT_READY` is emitted while the thread is not holding the GVL, and thus it can be in parallel with +other things +* All events are emitted _for all Ractors_, and each Ractor has their own GVL (yes yes, naming, see +[the talk linked into](https://ivoanjo.me/blog/2023/07/23/understanding-the-ruby-global-vm-lock-by-observing-it/) for a discussion on this) +* With the Ruby M:N threading, a native thread may play host to multiple Ruby threads so let's not assume too much + +All of the above taken together mean that we need to be very careful with what state we mutate or access from `on_gvl_event`, as they +can be concurrent with other operations in the profiler (including sampling). + +(The current implementation is similar to GC profiling, which shares similar constraints and limitations in not being able to sample +from the VM callbacks and also messing with cpu/wall-time accounting for threads that are GCing.) + +The `ThreadContext` collector exposes three APIs for GVL profiling: + +* `void thread_context_collector_on_gvl_waiting(VALUE thread)` +* `bool thread_context_collector_on_gvl_running(VALUE thread)` +* `VALUE thread_context_collector_sample_after_gvl_running(VALUE self_instance)` + +The intuition here is that: + +* `on_gvl_waiting` tracks when a thread began Waiting for GVL. It should be called when a thread +reports `RUBY_INTERNAL_THREAD_EVENT_READY` +* `on_gvl_running` tracks when a thread acquired the GVL. It should be called when a thread reports +`RUBY_INTERNAL_THREAD_EVENT_RESUMED` +* `sample_after_gvl_running` is the one that actually triggers the creation of a sample to represent +the waiting period. It should be called via the VM postponed job API when `on_gvl_running` returns `true`; e.g. when the +`ThreadContext` collector reports a sample should be taken. + +As far as the `CpuAndWallTimeWorker` cares, the above is all it needs to call in response to VM events. You'll notice +that `on_gvl_waiting` and `on_gvl_running` don't need or use any of the `CpuAndWallTimeWorker` or `ThreadContext` +instance state. + +The `sample_after_gvl_running` actually does, and that's why it's supposed to be used from a postponed job, which +ensures there's no concurrency (in our setup it only gets called with the GVL + on the main ractor) and thus we're safe to +access and mutate state inside it. + +### Tracking thread state and sampling in `ThreadContext` + +The weirdest piece of this puzzle is done in the `ThreadContext` collector. Because, as mentioned above, +`on_gvl_waiting` and `on_gvl_running` can get called outside the GVL/in other Ractors, we avoid touching the current +`ThreadContext` instance state in these methods. + +Instead, we ask Ruby to hold the data we need for us using the `rb_internal_thread_specific` API. This API provides +an extremely low-level and limited thread-local storage mechanism, but one that's thread-safe and thus a good match +for our needs. (This API is only available on Ruby 3.3+; to support Ruby 3.2 we'll need to figure out an alternative.) + +So, here's how this works: the first time the `ThreadContext` collector sees a thread (e.g. when it creates a context +for it), it uses this API to tag this thread as a thread we want to know about: + +```c +rb_internal_thread_specific_set(thread, per_thread_gvl_waiting_timestamp_key, (void *) GVL_WAITING_ENABLED_EMPTY); +``` + +From here on out, `on_gvl_waiting` and `on_gvl_running` know that if a thread has the `per_thread_gvl_waiting_timestamp` +variable set (to any other value than the default of `NULL`/0), it means this thread is known by the `ThreadContext` +collector and thus we should record data about it. +(And threads not in the main Ractor don't get this marker so this is one way we filter them out.) + +Could we have stored a pointer to the thread context directly on the thread? Potentially, yes, but we'd need to be +extremely careful when accessing thread contexts and when cleaning them up. (Maybe we'll evolve in this direction in +the future?) + +With the storage problem solved, here's what happens: the first part is that `on_gvl_waiting` records a timestamp for +when waiting started in the thread in `per_thread_gvl_waiting_timestamp`. + +Then, `on_gvl_running` checks the duration of the waiting (e.g. time between waiting started and current time). This +is a mechanism for reducing overhead: we'll produce at least two samples for every "Waiting for GVL" event that +we choose to sample, so we need to be careful not to allow situations with a lot of threads waiting for very brief +periods to induce too much overhead on the application. + +If we decide to sample (duration >= some minimal threshold duration for sampling), we can't sample yet! +As documented above, `on_gvl_running` is called in response to VM `RUBY_INTERNAL_THREAD_EVENT_RESUMED` events that +happen right after the thread acquired the GVL but there's still some book-keeping to do. Thus, we don't sample +from this method, but use the `bool` return to signal the caller when a sample should be taken. + +Then, a sample is taken once the caller (`CpuAndWallTimeWorker`) calls into `sample_after_gvl_running`. +This design is similar to GC profiling, where we also can't sample during GC, and thus we trigger a sample to happen immediately after. + +### Representing the Waiting for GVL in `ThreadContext` + +As far as sampling goes, we represent a Waiting for GVL as a thread state, similar to other thread states we emit. +This state is special, as it "overrides" other states, e.g. if a thread was sleeping, but wants to wake up, even +though the thread is still inside `sleep`, it will have the "Waiting for GVL" state. + +Waiting for GVL does not affect the regular flamegraph, only the timeline visualization, as it's a thread state, and +currently we do not represent thread states in any way on the regular flamegraph. + +The timestamp of the beginning of waiting for GVL gets used to create a sample that represents the "Waiting for GVL" +period. Because there's some unaccounted for cpu and wall-time between the previous sample and the start of a waiting +period, we also create a sample to account for this. + +There's some (lovely?) ASCII art in `handle_gvl_waiting` to explain how we create these two samples. + +Once a thread is in the "Waiting for GVL" state, then all regular cpu/wall-time samples triggered by the `CpuAndWallTimeWorker` +will continue to mark the thread as being in this state, until `on_gvl_running` + `sample_after_gvl_running` happen and +clear the `per_thread_gvl_waiting_timestamp`, which will make samples revert back to the regular behavior. From 90f1aa3630d36ed1720d8aad87a79dd417552f2d Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 14:58:42 +0100 Subject: [PATCH 38/42] Minor linting autofix --- spec/datadog/profiling/component_spec.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/datadog/profiling/component_spec.rb b/spec/datadog/profiling/component_spec.rb index 26884eb5a5b..9389625436b 100644 --- a/spec/datadog/profiling/component_spec.rb +++ b/spec/datadog/profiling/component_spec.rb @@ -628,7 +628,7 @@ context "when timeline is disabled" do before { settings.profiling.advanced.timeline_enabled = false } - it "does not enable GVL profiling" do + it "does not enable GVL profiling" do expect(Datadog::Profiling::Collectors::CpuAndWallTimeWorker) .to receive(:new).with(hash_including(gvl_profiling_enabled: false)) From 567a98c759a4fda9eaf60c6095f651c0da8dcf89 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 15:05:44 +0100 Subject: [PATCH 39/42] Fix skipping on legacy Rubies not stopping the profiler This skip was only called after a previous before started the profiler, so this left the test suite in an incorrect state. --- .../profiling/collectors/cpu_and_wall_time_worker_spec.rb | 2 +- spec/datadog/profiling/spec_helper.rb | 7 +++++-- 2 files changed, 6 insertions(+), 3 deletions(-) diff --git a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb index 4f2c073d655..7bf17c4f286 100644 --- a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb +++ b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb @@ -967,7 +967,7 @@ end context "when GVL profiling is enabled" do - before { skip_if_gvl_profiling_not_supported(self) } + before { skip_if_gvl_profiling_not_supported(self) { stop } } let(:gvl_profiling_enabled) { true } diff --git a/spec/datadog/profiling/spec_helper.rb b/spec/datadog/profiling/spec_helper.rb index 205000b7f32..f04211f9043 100644 --- a/spec/datadog/profiling/spec_helper.rb +++ b/spec/datadog/profiling/spec_helper.rb @@ -122,8 +122,11 @@ def self.maybe_fix_label_range(key, value) end end - def skip_if_gvl_profiling_not_supported(testcase) - testcase.skip "GVL profiling is only supported on Ruby >= 3.3" if RUBY_VERSION < "3.3." + def skip_if_gvl_profiling_not_supported(testcase, &skip_steps) + if RUBY_VERSION < "3.3." + yield if skip_steps + testcase.skip "GVL profiling is only supported on Ruby >= 3.3" + end end end From ea2bb1b3e076f316a94062c93d311c990abe8340 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 15:09:05 +0100 Subject: [PATCH 40/42] Split up variants of `_native_gvl_profiling_hook_active` to fix unused argument warning --- .../collectors_cpu_and_wall_time_worker.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index a04303f021d..8ba916dd759 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -1339,15 +1339,15 @@ static VALUE _native_resume_signals(DDTRACE_UNUSED VALUE self) { state->during_sample = false; } -#endif -static VALUE _native_gvl_profiling_hook_active(DDTRACE_UNUSED VALUE self, VALUE instance) { - #ifndef NO_GVL_INSTRUMENTATION + static VALUE _native_gvl_profiling_hook_active(DDTRACE_UNUSED VALUE self, VALUE instance) { struct cpu_and_wall_time_worker_state *state; TypedData_Get_Struct(instance, struct cpu_and_wall_time_worker_state, &cpu_and_wall_time_worker_typed_data, state); return state->gvl_profiling_hook != NULL ? Qtrue : Qfalse; - #else + } +#else + static VALUE _native_gvl_profiling_hook_active(DDTRACE_UNUSED VALUE self, DDTRACE_UNUSED VALUE instance) { return Qfalse; - #endif -} + } +#endif From 82aa51a5cdc0d26e7d39d3e812cbcd852651f3c2 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 18 Sep 2024 15:12:45 +0100 Subject: [PATCH 41/42] Disable GC profiling in spec to avoid dealing with warning --- spec/datadog/profiling/component_spec.rb | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/spec/datadog/profiling/component_spec.rb b/spec/datadog/profiling/component_spec.rb index 9389625436b..83b11f0c7ed 100644 --- a/spec/datadog/profiling/component_spec.rb +++ b/spec/datadog/profiling/component_spec.rb @@ -592,7 +592,11 @@ end context "when GVL profiling is requested" do - before { settings.profiling.advanced.preview_gvl_enabled = true } + before do + settings.profiling.advanced.preview_gvl_enabled = true + # This triggers a warning in some Rubies so it's easier for testing to disable it + settings.profiling.advanced.gc_enabled = false + end context "on Ruby < 3.3" do before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION >= "3.3." } From c4438936dea06990bcda3d6084a881465df08077 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Fri, 20 Sep 2024 10:17:13 +0100 Subject: [PATCH 42/42] Raise ArgumentError when trying to use GVL profiling on unsupported Rubies --- .../collectors_cpu_and_wall_time_worker.c | 10 ++++++---- .../cpu_and_wall_time_worker_spec.rb | 20 +++++++++++++++---- spec/datadog/profiling/spec_helper.rb | 3 +-- 3 files changed, 23 insertions(+), 10 deletions(-) diff --git a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c index 8ba916dd759..591354a906b 100644 --- a/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c +++ b/ext/datadog_profiling_native_extension/collectors_cpu_and_wall_time_worker.c @@ -802,8 +802,8 @@ static VALUE release_gvl_and_run_sampling_trigger_loop(VALUE instance) { ; } - #ifndef NO_GVL_INSTRUMENTATION - if (state->gvl_profiling_enabled) { + if (state->gvl_profiling_enabled) { + #ifndef NO_GVL_INSTRUMENTATION state->gvl_profiling_hook = rb_internal_thread_add_event_hook( on_gvl_event, ( @@ -814,8 +814,10 @@ static VALUE release_gvl_and_run_sampling_trigger_loop(VALUE instance) { ), NULL ); - } - #endif + #else + rb_raise(rb_eArgError, "GVL profiling is not supported in this Ruby version"); + #endif + } // Flag the profiler as running before we release the GVL, in case anyone's waiting to know about it rb_funcall(instance, rb_intern("signal_running"), 0); diff --git a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb index 7bf17c4f286..c39971c3f23 100644 --- a/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb +++ b/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb @@ -148,6 +148,18 @@ end end + context "when gvl_profiling_enabled is true on an unsupported Ruby" do + before { skip "Behavior does not apply to current Ruby version" if RUBY_VERSION >= "3.3." } + + let(:gvl_profiling_enabled) { true } + + it do + expect(Datadog.logger).to receive(:warn).with(/GVL profiling is not supported/) + + cpu_and_wall_time_worker.start + end + end + context "when gvl_profiling_enabled is false" do let(:gvl_profiling_enabled) { false } @@ -935,6 +947,8 @@ context "after starting" do before do + skip_if_gvl_profiling_not_supported(self) if gvl_profiling_enabled + cpu_and_wall_time_worker.start wait_until_running end @@ -967,8 +981,6 @@ end context "when GVL profiling is enabled" do - before { skip_if_gvl_profiling_not_supported(self) { stop } } - let(:gvl_profiling_enabled) { true } it "disables the GVL profiling hook" do @@ -1005,6 +1017,8 @@ let(:options) { {thread_context_collector: thread_context_collector} } before do + skip_if_gvl_profiling_not_supported(self) if gvl_profiling_enabled + # This is important -- the real #reset_after_fork must not be called concurrently with the worker running, # which we do in this spec to make it easier to test the reset_after_fork behavior allow(thread_context_collector).to receive(:reset_after_fork) @@ -1024,8 +1038,6 @@ end context "when gvl_profiling_enabled is true" do - before { skip_if_gvl_profiling_not_supported(self) } - let(:gvl_profiling_enabled) { true } it "disables the gvl profiling hook" do diff --git a/spec/datadog/profiling/spec_helper.rb b/spec/datadog/profiling/spec_helper.rb index f04211f9043..f8131391114 100644 --- a/spec/datadog/profiling/spec_helper.rb +++ b/spec/datadog/profiling/spec_helper.rb @@ -122,9 +122,8 @@ def self.maybe_fix_label_range(key, value) end end - def skip_if_gvl_profiling_not_supported(testcase, &skip_steps) + def skip_if_gvl_profiling_not_supported(testcase) if RUBY_VERSION < "3.3." - yield if skip_steps testcase.skip "GVL profiling is only supported on Ruby >= 3.3" end end