From 74cde8a8aef2667b1577c07e88f323235349d43e Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 5 Jul 2023 10:29:22 +0100 Subject: [PATCH 1/5] Add code to retrieve invoke location of a thread --- .../private_vm_api_access.c | 31 +++++++++++++++++++ .../private_vm_api_access.h | 6 ++++ 2 files changed, 37 insertions(+) diff --git a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c index a9b6b864cd7..1530bd8ae25 100644 --- a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c +++ b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c @@ -767,3 +767,34 @@ check_method_entry(VALUE obj, int can_be_svar) // they're always on the main Ractor bool ddtrace_rb_ractor_main_p(void) { return true; } #endif // NO_RACTORS + +// This is a tweaked and inlined version of +// threadptr_invoke_proc_location + rb_proc_location + iseq_location . +// +// It's useful to have here because not all of the methods above are accessible to extensions + to avoid the +// array allocation that iseq_location did to contain its return value. +static const rb_iseq_t *maybe_thread_invoke_proc_iseq(VALUE thread_value) { + rb_thread_t *thread = thread_struct_from_object(thread_value); + + if (thread->invoke_type != thread_invoke_type_proc) return NULL; + + VALUE iseq_value = thread->invoke_arg.proc.proc; + + const rb_iseq_t *iseq = rb_proc_get_iseq(iseq_value, 0); + if (iseq == NULL) return NULL; + + rb_iseq_check(iseq); + return iseq; +} + +VALUE invoke_file_location_for(VALUE thread) { + const rb_iseq_t *iseq = maybe_thread_invoke_proc_iseq(thread); + + return iseq != NULL ? rb_iseq_path(iseq) : Qnil; +} + +VALUE invoke_line_location_for(VALUE thread) { + const rb_iseq_t *iseq = maybe_thread_invoke_proc_iseq(thread); + + return iseq != NULL ? RB_INT2NUM(ISEQ_BODY(iseq)->location.first_lineno) : Qnil; +} diff --git a/ext/ddtrace_profiling_native_extension/private_vm_api_access.h b/ext/ddtrace_profiling_native_extension/private_vm_api_access.h index 62f39c52f30..ba82ff4755b 100644 --- a/ext/ddtrace_profiling_native_extension/private_vm_api_access.h +++ b/ext/ddtrace_profiling_native_extension/private_vm_api_access.h @@ -43,3 +43,9 @@ bool ddtrace_rb_ractor_main_p(void); // See comment on `record_placeholder_stack_in_native_code` for a full explanation of what this means (and why we don't just return 0) #define PLACEHOLDER_STACK_IN_NATIVE_CODE -1 + +// These methods provide the file and line of the "invoke location" of a thread (first file:line of the block used to +// start the thread), if any. +// This is what Ruby shows in `Thread#to_s`. +VALUE invoke_file_location_for(VALUE thread); +VALUE invoke_line_location_for(VALUE thread); From b39f0130cef599c8eb4c8d49623196d11c34d7e2 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 5 Jul 2023 11:02:46 +0100 Subject: [PATCH 2/5] Record thread_invoke_location for each per_thread_context The `thread_invoke_location` can be used as a fallback alternative for threads that have no name, and is what Ruby shows in `Thread#to_s` as well. This commit only gathers the invoke location and stores it in the context; this information is not yet propagated in the pprof, that will come in a later commit. --- .../collectors_thread_context.c | 25 +++++++++++++++++++ .../private_vm_api_access.c | 6 ++--- .../collectors/thread_context_spec.rb | 18 +++++++++++++ 3 files changed, 46 insertions(+), 3 deletions(-) diff --git a/ext/ddtrace_profiling_native_extension/collectors_thread_context.c b/ext/ddtrace_profiling_native_extension/collectors_thread_context.c index af6b566ccf1..d60bbafebd4 100644 --- a/ext/ddtrace_profiling_native_extension/collectors_thread_context.c +++ b/ext/ddtrace_profiling_native_extension/collectors_thread_context.c @@ -64,6 +64,7 @@ // --- #define THREAD_ID_LIMIT_CHARS 44 // Why 44? "#{2**64} (#{2**64})".size + 1 for \0 +#define THREAD_INVOKE_LOCATION_LIMIT_CHARS 512 #define IS_WALL_TIME true #define IS_NOT_WALL_TIME false #define MISSING_TRACER_CONTEXT_KEY 0 @@ -117,6 +118,8 @@ struct thread_context_collector_state { struct per_thread_context { char thread_id[THREAD_ID_LIMIT_CHARS]; ddog_CharSlice thread_id_char_slice; + char thread_invoke_location[THREAD_INVOKE_LOCATION_LIMIT_CHARS]; + ddog_CharSlice thread_invoke_location_char_slice; thread_cpu_time_id thread_cpu_time_id; long cpu_time_at_previous_sample_ns; // Can be INVALID_TIME until initialized or if getting it fails for another reason long wall_time_at_previous_sample_ns; // Can be INVALID_TIME until initialized @@ -757,6 +760,27 @@ static void initialize_context(VALUE thread, struct per_thread_context *thread_c snprintf(thread_context->thread_id, THREAD_ID_LIMIT_CHARS, "%"PRIu64" (%lu)", native_thread_id_for(thread), (unsigned long) thread_id_for(thread)); thread_context->thread_id_char_slice = (ddog_CharSlice) {.ptr = thread_context->thread_id, .len = strlen(thread_context->thread_id)}; + VALUE invoke_file_location = invoke_file_location_for(thread); + VALUE invoke_line_location = invoke_line_location_for(thread); + if (invoke_file_location != Qnil) { + if (invoke_line_location == Qnil) invoke_line_location = RB_INT2NUM(0); + + snprintf( + thread_context->thread_invoke_location, + THREAD_INVOKE_LOCATION_LIMIT_CHARS, + "%s:%d", + StringValueCStr(invoke_file_location), + NUM2INT(invoke_line_location) + ); + } else { + snprintf(thread_context->thread_invoke_location, THREAD_INVOKE_LOCATION_LIMIT_CHARS, "%s", ""); + } + + thread_context->thread_invoke_location_char_slice = (ddog_CharSlice) { + .ptr = thread_context->thread_invoke_location, + .len = strlen(thread_context->thread_invoke_location) + }; + thread_context->thread_cpu_time_id = thread_cpu_time_id_for(thread); // These will get initialized during actual sampling @@ -810,6 +834,7 @@ static int per_thread_context_as_ruby_hash(st_data_t key_thread, st_data_t value VALUE arguments[] = { ID2SYM(rb_intern("thread_id")), /* => */ rb_str_new2(thread_context->thread_id), + ID2SYM(rb_intern("thread_invoke_location")), /* => */ rb_str_new2(thread_context->thread_invoke_location), ID2SYM(rb_intern("thread_cpu_time_id_valid?")), /* => */ thread_context->thread_cpu_time_id.valid ? Qtrue : Qfalse, ID2SYM(rb_intern("thread_cpu_time_id")), /* => */ CLOCKID2NUM(thread_context->thread_cpu_time_id.clock_id), ID2SYM(rb_intern("cpu_time_at_previous_sample_ns")), /* => */ LONG2NUM(thread_context->cpu_time_at_previous_sample_ns), diff --git a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c index 1530bd8ae25..cda43bd83ff 100644 --- a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c +++ b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c @@ -778,9 +778,9 @@ static const rb_iseq_t *maybe_thread_invoke_proc_iseq(VALUE thread_value) { if (thread->invoke_type != thread_invoke_type_proc) return NULL; - VALUE iseq_value = thread->invoke_arg.proc.proc; + VALUE proc = thread->invoke_arg.proc.proc; - const rb_iseq_t *iseq = rb_proc_get_iseq(iseq_value, 0); + const rb_iseq_t *iseq = rb_proc_get_iseq(proc, 0); if (iseq == NULL) return NULL; rb_iseq_check(iseq); @@ -796,5 +796,5 @@ VALUE invoke_file_location_for(VALUE thread) { VALUE invoke_line_location_for(VALUE thread) { const rb_iseq_t *iseq = maybe_thread_invoke_proc_iseq(thread); - return iseq != NULL ? RB_INT2NUM(ISEQ_BODY(iseq)->location.first_lineno) : Qnil; + return iseq != NULL ? rb_iseq_first_lineno(iseq) : Qnil; } diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 0ce30c1f445..a829fb72701 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -1086,6 +1086,24 @@ def another_way_of_calling_sample(profiler_overhead_stack_thread: Thread.current end end end + + describe ':thread_invoke_location' do + it 'is empty for the main thread' do + expect(per_thread_context.fetch(Thread.main).fetch(:thread_invoke_location)).to be_empty + end + + # NOTE: As of this writing, the dd-trace-rb spec_helper.rb includes a monkey patch to Thread creation that we use + # to track specs that leak threads. This means that the invoke_location of every thread will point at the + # spec_helper in our test suite. Just in case you're looking at the output and being a bit confused :) + it 'contains the file and line for the started threads' do + [t1, t2, t3].each do |thread| + invoke_location = per_thread_context.fetch(thread).fetch(:thread_invoke_location) + + expect(thread.to_s).to include(invoke_location) + expect(invoke_location).to match(/.+\.rb:\d+/) + end + end + end end context 'after sampling multiple times' do From deca23709f8698a5fe574fb5e5c5056570020f76 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 5 Jul 2023 16:49:01 +0100 Subject: [PATCH 3/5] [PROF-7440] Use invoke location as a fallback for nameless threads in the profiler **What does this PR do?**: Naming Ruby threads is optional, and a lot of Ruby code still creates threads and doesn't name them. As a workaround for Ruby threads that have no name, this PR makes the profiler use the "thread invoke location", which is what Ruby shows in the `to_s`/`inspect` of a thread, for instance: ``` [1] pry(main)> Thread.list.last.name => nil [2] pry(main)> Thread.list.last.to_s => "#" ``` The "invoke location" is the file and line where the block that starts the thread is defined. **Motivation**: Having nameless threads is annoying because we show this information in several places of our UX, and with the timeline feature this will be even more visible. **Additional Notes**: Since Ruby doesn't have an API to get this information (other than calling `to_s` and then parsing its output), and because we want to avoid allocating any Ruby objects while the profiler is taking a sample, I chose to add to `private_vm_api_access.c` an API to get this information that is basically a heavily simplified version of `Thread#to_s`. **How to test the change?**: This change includes code coverage. Also, profile any app that starts and doesn't name threads, and you'll start seeing threads named "some_file.rb:some_line" in the profiler. --- .../collectors_thread_context.c | 7 +++++ .../collectors/thread_context_spec.rb | 26 ++++++++++++------- 2 files changed, 24 insertions(+), 9 deletions(-) diff --git a/ext/ddtrace_profiling_native_extension/collectors_thread_context.c b/ext/ddtrace_profiling_native_extension/collectors_thread_context.c index d60bbafebd4..411d0333320 100644 --- a/ext/ddtrace_profiling_native_extension/collectors_thread_context.c +++ b/ext/ddtrace_profiling_native_extension/collectors_thread_context.c @@ -663,6 +663,13 @@ static void trigger_sample_for_thread( .key = DDOG_CHARSLICE_C("thread name"), .str = main_thread_name }; + } else { + // For other threads without name, we use the "invoke location" (first file:line of the block used to start the thread), if any. + // This is what Ruby shows in `Thread#to_s`. + labels[label_pos++] = (ddog_prof_Label) { + .key = DDOG_CHARSLICE_C("thread name"), + .str = thread_context->thread_invoke_location_char_slice // This is an empty string if no invoke location was available + }; } struct trace_identifiers trace_identifiers_result = {.valid = false, .trace_endpoint = Qnil}; diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index a829fb72701..2c3037209a0 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -116,20 +116,31 @@ def another_way_of_calling_sample(profiler_overhead_stack_thread: Thread.current .to include(*[Thread.main, t1, t2, t3].map(&:object_id)) end - it 'includes the thread names, if available' do + it 'includes the thread names' do t1.name = 'thread t1' - t2.name = nil - t3.name = 'thread t3' + t2.name = 'thread t2' sample t1_sample = samples_for_thread(samples, t1).first t2_sample = samples_for_thread(samples, t2).first - t3_sample = samples_for_thread(samples, t3).first expect(t1_sample.labels).to include(:'thread name' => 'thread t1') - expect(t2_sample.labels.keys).to_not include(:'thread name') - expect(t3_sample.labels).to include(:'thread name' => 'thread t3') + expect(t2_sample.labels).to include(:'thread name' => 'thread t2') + end + + context 'when no thread names are available' do + # NOTE: As of this writing, the dd-trace-rb spec_helper.rb includes a monkey patch to Thread creation that we use + # to track specs that leak threads. This means that the invoke_location of every thread will point at the + # spec_helper in our test suite. Just in case you're looking at the output and being a bit confused :) + it 'uses the thread_invoke_location as a thread name' do + t1.name = nil + sample + t1_sample = samples_for_thread(samples, t1).first + + expect(t1_sample.labels).to include(:'thread name' => per_thread_context.fetch(t1).fetch(:thread_invoke_location)) + expect(t1_sample.labels).to include(:'thread name' => match(/.+\.rb:\d+/)) + end end it 'includes a fallback name for the main thread, when not set' do @@ -918,13 +929,10 @@ def another_way_of_calling_sample(profiler_overhead_stack_thread: Thread.current Thread.current.name = 'thread_with_name' sample_allocation(weight: 123) end.join - thread_without_name = Thread.new { sample_allocation(weight: 123) }.join sample_with_name = samples_for_thread(samples, thread_with_name).first - sample_without_name = samples_for_thread(samples, thread_without_name).first expect(sample_with_name.labels).to include(:'thread name' => 'thread_with_name') - expect(sample_without_name.labels).to_not include(:'thread name') end describe 'code hotspots' do From 2d6813d3c4efb14558de02e24cdcfe787f509941 Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Wed, 5 Jul 2023 17:22:33 +0100 Subject: [PATCH 4/5] Fix support for reading the thread invoke proc on Ruby < 2.6 Arghhh old Rubies... --- ext/ddtrace_profiling_native_extension/extconf.rb | 3 +++ .../private_vm_api_access.c | 10 ++++++++-- .../profiling/collectors/thread_context_spec.rb | 2 +- 3 files changed, 12 insertions(+), 3 deletions(-) diff --git a/ext/ddtrace_profiling_native_extension/extconf.rb b/ext/ddtrace_profiling_native_extension/extconf.rb index 8f7ca0fb619..f0314ea3288 100644 --- a/ext/ddtrace_profiling_native_extension/extconf.rb +++ b/ext/ddtrace_profiling_native_extension/extconf.rb @@ -155,6 +155,9 @@ def add_compiler_flag(flag) # On older Rubies, rb_global_vm_lock_struct did not include the owner field $defs << '-DNO_GVL_OWNER' if RUBY_VERSION < '2.6' +# On older Rubies, there was no thread->invoke_arg +$defs << '-DNO_THREAD_INVOKE_ARG' if RUBY_VERSION < '2.6' + # On older Rubies, we need to use rb_thread_t instead of rb_execution_context_t $defs << '-DUSE_THREAD_INSTEAD_OF_EXECUTION_CONTEXT' if RUBY_VERSION < '2.5' diff --git a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c index cda43bd83ff..24c52f4cf5e 100644 --- a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c +++ b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c @@ -776,9 +776,15 @@ check_method_entry(VALUE obj, int can_be_svar) static const rb_iseq_t *maybe_thread_invoke_proc_iseq(VALUE thread_value) { rb_thread_t *thread = thread_struct_from_object(thread_value); - if (thread->invoke_type != thread_invoke_type_proc) return NULL; + #ifndef NO_THREAD_INVOKE_ARG // Ruby 2.6+ + if (thread->invoke_type != thread_invoke_type_proc) return NULL; - VALUE proc = thread->invoke_arg.proc.proc; + VALUE proc = thread->invoke_arg.proc.proc; + #else + if (thread->first_func || !thread->first_proc) return NULL; + + VALUE proc = thread->first_proc; + #endif const rb_iseq_t *iseq = rb_proc_get_iseq(proc, 0); if (iseq == NULL) return NULL; diff --git a/spec/datadog/profiling/collectors/thread_context_spec.rb b/spec/datadog/profiling/collectors/thread_context_spec.rb index 2c3037209a0..aea9009eac5 100644 --- a/spec/datadog/profiling/collectors/thread_context_spec.rb +++ b/spec/datadog/profiling/collectors/thread_context_spec.rb @@ -1107,7 +1107,7 @@ def another_way_of_calling_sample(profiler_overhead_stack_thread: Thread.current [t1, t2, t3].each do |thread| invoke_location = per_thread_context.fetch(thread).fetch(:thread_invoke_location) - expect(thread.to_s).to include(invoke_location) + expect(thread.inspect).to include(invoke_location) expect(invoke_location).to match(/.+\.rb:\d+/) end end From 87bd64e1f0eea09538ddaf73028bc6104ec73fee Mon Sep 17 00:00:00 2001 From: Ivo Anjo Date: Thu, 6 Jul 2023 09:10:13 +0100 Subject: [PATCH 5/5] Merge invoke_file_location_for and invoke_line_location_for into single method This avoids doing the iseq lookup twice. --- .../collectors_thread_context.c | 8 +++----- .../private_vm_api_access.c | 11 ++++------- .../private_vm_api_access.h | 6 +++--- 3 files changed, 10 insertions(+), 15 deletions(-) diff --git a/ext/ddtrace_profiling_native_extension/collectors_thread_context.c b/ext/ddtrace_profiling_native_extension/collectors_thread_context.c index 411d0333320..91dc38b8810 100644 --- a/ext/ddtrace_profiling_native_extension/collectors_thread_context.c +++ b/ext/ddtrace_profiling_native_extension/collectors_thread_context.c @@ -767,17 +767,15 @@ static void initialize_context(VALUE thread, struct per_thread_context *thread_c snprintf(thread_context->thread_id, THREAD_ID_LIMIT_CHARS, "%"PRIu64" (%lu)", native_thread_id_for(thread), (unsigned long) thread_id_for(thread)); thread_context->thread_id_char_slice = (ddog_CharSlice) {.ptr = thread_context->thread_id, .len = strlen(thread_context->thread_id)}; - VALUE invoke_file_location = invoke_file_location_for(thread); - VALUE invoke_line_location = invoke_line_location_for(thread); + int invoke_line_location; + VALUE invoke_file_location = invoke_location_for(thread, &invoke_line_location); if (invoke_file_location != Qnil) { - if (invoke_line_location == Qnil) invoke_line_location = RB_INT2NUM(0); - snprintf( thread_context->thread_invoke_location, THREAD_INVOKE_LOCATION_LIMIT_CHARS, "%s:%d", StringValueCStr(invoke_file_location), - NUM2INT(invoke_line_location) + invoke_line_location ); } else { snprintf(thread_context->thread_invoke_location, THREAD_INVOKE_LOCATION_LIMIT_CHARS, "%s", ""); diff --git a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c index 8ed1719b76f..e2461c838b5 100644 --- a/ext/ddtrace_profiling_native_extension/private_vm_api_access.c +++ b/ext/ddtrace_profiling_native_extension/private_vm_api_access.c @@ -798,14 +798,11 @@ static const rb_iseq_t *maybe_thread_invoke_proc_iseq(VALUE thread_value) { return iseq; } -VALUE invoke_file_location_for(VALUE thread) { +VALUE invoke_location_for(VALUE thread, int *line_location) { const rb_iseq_t *iseq = maybe_thread_invoke_proc_iseq(thread); - return iseq != NULL ? rb_iseq_path(iseq) : Qnil; -} - -VALUE invoke_line_location_for(VALUE thread) { - const rb_iseq_t *iseq = maybe_thread_invoke_proc_iseq(thread); + if (iseq == NULL) return Qnil; - return iseq != NULL ? rb_iseq_first_lineno(iseq) : Qnil; + *line_location = NUM2INT(rb_iseq_first_lineno(iseq)); + return rb_iseq_path(iseq); } diff --git a/ext/ddtrace_profiling_native_extension/private_vm_api_access.h b/ext/ddtrace_profiling_native_extension/private_vm_api_access.h index ba82ff4755b..608a25f7198 100644 --- a/ext/ddtrace_profiling_native_extension/private_vm_api_access.h +++ b/ext/ddtrace_profiling_native_extension/private_vm_api_access.h @@ -44,8 +44,8 @@ bool ddtrace_rb_ractor_main_p(void); // See comment on `record_placeholder_stack_in_native_code` for a full explanation of what this means (and why we don't just return 0) #define PLACEHOLDER_STACK_IN_NATIVE_CODE -1 -// These methods provide the file and line of the "invoke location" of a thread (first file:line of the block used to +// This method provides the file and line of the "invoke location" of a thread (first file:line of the block used to // start the thread), if any. // This is what Ruby shows in `Thread#to_s`. -VALUE invoke_file_location_for(VALUE thread); -VALUE invoke_line_location_for(VALUE thread); +// The file is returned directly, and the line is recorded onto *line_location. +VALUE invoke_location_for(VALUE thread, int *line_location);