Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[PROF-7440] Add workaround for incorrect invoke location when logging gem is in use #3183

Merged
merged 2 commits into from
Oct 4, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -815,20 +815,45 @@ static struct per_thread_context *get_context_for(VALUE thread, struct thread_co
return thread_context;
}

#define LOGGING_GEM_PATH "/lib/logging/diagnostic_context.rb"

// The `logging` gem monkey patches thread creation, which makes the `invoke_location_for` useless, since every thread
// will point to the `logging` gem. When that happens, we avoid using the invoke location.
//
// TODO: This approach is a bit brittle, since it matches on the specific gem path, and only works for the `logging`
// gem.
// In the future we should probably explore a more generic fix (e.g. using Thread.method(:new).source_location or
// something like that to detect redefinition of the `Thread` methods). One difficulty of doing it is that we need
// to either run Ruby code during sampling (not great), or otherwise use some of the VM private APIs to detect this.
//
static bool is_logging_gem_monkey_patch(VALUE invoke_file_location) {
int logging_gem_path_len = strlen(LOGGING_GEM_PATH);
char *invoke_file = StringValueCStr(invoke_file_location);
int invoke_file_len = strlen(invoke_file);

if (invoke_file_len < logging_gem_path_len) return false;

return strncmp(invoke_file + invoke_file_len - logging_gem_path_len, LOGGING_GEM_PATH, logging_gem_path_len) == 0;
}

static void initialize_context(VALUE thread, struct per_thread_context *thread_context, struct thread_context_collector_state *state) {
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)};

int invoke_line_location;
VALUE invoke_file_location = invoke_location_for(thread, &invoke_line_location);
if (invoke_file_location != Qnil) {
snprintf(
thread_context->thread_invoke_location,
THREAD_INVOKE_LOCATION_LIMIT_CHARS,
"%s:%d",
StringValueCStr(invoke_file_location),
invoke_line_location
);
if (!is_logging_gem_monkey_patch(invoke_file_location)) {
snprintf(
thread_context->thread_invoke_location,
THREAD_INVOKE_LOCATION_LIMIT_CHARS,
"%s:%d",
StringValueCStr(invoke_file_location),
invoke_line_location
);
} else {
snprintf(thread_context->thread_invoke_location, THREAD_INVOKE_LOCATION_LIMIT_CHARS, "%s", "(Unnamed thread)");
}
} else if (thread != state->main_thread) {
// If the first function of a thread is native code, there won't be an invoke location, so we use this fallback.
// NOTE: In the future, I wonder if we could take the pointer to the native function, and try to see if there's a native
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,12 @@
# This file is used by the `thread_context_spec.rb`. It's used to simulate the file from the `logging` gem on the same
# partial path. See that file for more details.

# rubocop:disable Style/GlobalVars

$simulated_logging_gem_monkey_patched_thread_ready_queue = Queue.new
$simulated_logging_gem_monkey_patched_thread = Thread.start do
$simulated_logging_gem_monkey_patched_thread_ready_queue << true
sleep
end

# rubocop:enable Style/GlobalVars
30 changes: 30 additions & 0 deletions spec/datadog/profiling/collectors/thread_context_spec.rb
Original file line number Diff line number Diff line change
Expand Up @@ -1244,6 +1244,36 @@ def another_way_of_calling_sample(profiler_overhead_stack_thread: Thread.current
invoke_location = per_thread_context.fetch(native_thread).fetch(:thread_invoke_location)
expect(invoke_location).to eq '(Unnamed thread from native code)'
end

context 'when the `logging` gem has monkey patched thread creation' do
# rubocop:disable Style/GlobalVars
before do
load("#{__dir__}/helper/lib/logging/diagnostic_context.rb")
$simulated_logging_gem_monkey_patched_thread_ready_queue.pop
end

after do
$simulated_logging_gem_monkey_patched_thread.kill
$simulated_logging_gem_monkey_patched_thread.join
$simulated_logging_gem_monkey_patched_thread = nil
$simulated_logging_gem_monkey_patched_thread_ready_queue = nil
end

# We detect logging gem monkey patching by checking the invoke location of a thread and not using it when
# it belongs to the logging gem. This matching is done by matching the partial path
# `lib/logging/diagnostic_context.rb`, which is where the monkey patching is implemented.
#
# To simulate this on our test suite without having to bring in the `logging` gem (and monkey patch our
# threads), a helper was created that has a matching partial path.
it 'contains a placeholder only' do
sample

invoke_location =
per_thread_context.fetch($simulated_logging_gem_monkey_patched_thread).fetch(:thread_invoke_location)
expect(invoke_location).to eq '(Unnamed thread)'
end
# rubocop:enable Style/GlobalVars
end
end
end

Expand Down
Loading