From a138ec35eca1140a6766ba366a9ad672cdd524f7 Mon Sep 17 00:00:00 2001 From: Benoit Tigeot Date: Tue, 4 Apr 2023 09:00:14 +0200 Subject: [PATCH] Provide when possible the thread name and gem name gvl-tracing handles properly thread name for basic usage like: ```ruby Thread.new do Thread.current.name = "thread name end ``` But on more complicated with external libraries it is not able to properly handles thread name. Jean had a good idea in https://github.com/ivoanjo/gvl-tracing/issues/9 about using `Thread.list`. This commit does this: - Store as list of json line, events we want to monitor - Store `Thread.list` before stopping saving event related to the GVL - Iterate of events store in json file and modify entries where we can find the name of the thread - Go a little bit further when we can provide the gem name This is a very naive approach and probably not super efficient. But this is a first try. --- examples/thread_name_with_extension.json | 1 + examples/thread_name_with_extension.rb | 18 ++++++++ ext/gvl_tracing_native_extension/extconf.rb | 6 +-- .../gvl_tracing.c | 12 +++-- lib/gvl-tracing.rb | 44 +++++++++++++++++++ 5 files changed, 71 insertions(+), 10 deletions(-) create mode 100644 examples/thread_name_with_extension.json create mode 100644 examples/thread_name_with_extension.rb diff --git a/examples/thread_name_with_extension.json b/examples/thread_name_with_extension.json new file mode 100644 index 0000000..89f9193 --- /dev/null +++ b/examples/thread_name_with_extension.json @@ -0,0 +1 @@ +[{"ph":"M","pid":81742,"tid":0,"name":"thread_name","args":{"name":null}},{"ph":"E","pid":81742,"tid":0,"ts":0.0},{"ph":"B","pid":81742,"tid":0,"ts":0.0,"name":"started_tracing"},{"ph":"M","pid":81742,"tid":1,"name":"thread_name","args":{"name":"worker-1 from concurrent-ruby"}},{"ph":"E","pid":81742,"tid":1,"ts":62.0},{"ph":"B","pid":81742,"tid":1,"ts":62.0,"name":"started"},{"ph":"E","pid":81742,"tid":1,"ts":65.0},{"ph":"B","pid":81742,"tid":1,"ts":65.0,"name":"wants_gvl"},{"ph":"M","pid":81742,"tid":2,"name":"thread_name","args":{"name":"worker-2 from concurrent-ruby"}},{"ph":"E","pid":81742,"tid":2,"ts":76.0},{"ph":"B","pid":81742,"tid":2,"ts":76.0,"name":"started"},{"ph":"E","pid":81742,"tid":2,"ts":78.0},{"ph":"B","pid":81742,"tid":2,"ts":78.0,"name":"wants_gvl"},{"ph":"M","pid":81742,"tid":3,"name":"thread_name","args":{"name":"worker-3 from concurrent-ruby"}},{"ph":"E","pid":81742,"tid":3,"ts":88.0},{"ph":"B","pid":81742,"tid":3,"ts":88.0,"name":"started"},{"ph":"E","pid":81742,"tid":3,"ts":89.0},{"ph":"B","pid":81742,"tid":3,"ts":89.0,"name":"wants_gvl"},{"ph":"M","pid":81742,"tid":4,"name":"thread_name","args":{"name":"worker-4 from concurrent-ruby"}},{"ph":"E","pid":81742,"tid":4,"ts":97.0},{"ph":"B","pid":81742,"tid":4,"ts":97.0,"name":"started"},{"ph":"E","pid":81742,"tid":4,"ts":98.0},{"ph":"B","pid":81742,"tid":4,"ts":98.0,"name":"wants_gvl"},{"ph":"M","pid":81742,"tid":5,"name":"thread_name","args":{"name":"worker-5 from concurrent-ruby"}},{"ph":"E","pid":81742,"tid":5,"ts":106.0},{"ph":"B","pid":81742,"tid":5,"ts":106.0,"name":"started"},{"ph":"E","pid":81742,"tid":5,"ts":107.0},{"ph":"B","pid":81742,"tid":5,"ts":107.0,"name":"wants_gvl"},{"ph":"E","pid":81742,"tid":0,"ts":146.0},{"ph":"B","pid":81742,"tid":0,"ts":146.0,"name":"stopped_tracing"}] \ No newline at end of file diff --git a/examples/thread_name_with_extension.rb b/examples/thread_name_with_extension.rb new file mode 100644 index 0000000..c3bf160 --- /dev/null +++ b/examples/thread_name_with_extension.rb @@ -0,0 +1,18 @@ +# conrrent-ruby needs to be installed +require "concurrent" +require "gvl-tracing" + +def fib(n) + return n if n <= 1 + fib(n - 1) + fib(n - 2) +end + +GvlTracing.start("examples/thread_name_with_extension.json") +pool = Concurrent::FixedThreadPool.new(5) + +40.times do + pool.post do + p fib(30) + end +end +GvlTracing.stop diff --git a/ext/gvl_tracing_native_extension/extconf.rb b/ext/gvl_tracing_native_extension/extconf.rb index 54faf84..9f30a21 100644 --- a/ext/gvl_tracing_native_extension/extconf.rb +++ b/ext/gvl_tracing_native_extension/extconf.rb @@ -36,9 +36,9 @@ have_header("pthread.h") have_func("pthread_getname_np", "pthread.h") have_func("pthread_threadid_np", "pthread.h") -append_cflags('-Werror-implicit-function-declaration') -append_cflags('-Wunused-parameter') -append_cflags('-Wold-style-definition') +append_cflags("-Werror-implicit-function-declaration") +append_cflags("-Wunused-parameter") +append_cflags("-Wold-style-definition") append_cflags("-Wall") append_cflags("-Wextra") diff --git a/ext/gvl_tracing_native_extension/gvl_tracing.c b/ext/gvl_tracing_native_extension/gvl_tracing.c index ebcd06f..adc1df4 100644 --- a/ext/gvl_tracing_native_extension/gvl_tracing.c +++ b/ext/gvl_tracing_native_extension/gvl_tracing.c @@ -63,7 +63,7 @@ static VALUE gc_tracepoint = Qnil; void Init_gvl_tracing_native_extension(void) { rb_global_variable(&gc_tracepoint); - VALUE gvl_tracing_module = rb_define_module("GvlTracing"); + VALUE gvl_tracing_module = rb_define_module("GvlTracingNativeExtension"); rb_define_singleton_method(gvl_tracing_module, "start", tracing_start, 1); rb_define_singleton_method(gvl_tracing_module, "stop", tracing_stop, 0); @@ -91,7 +91,7 @@ static inline void render_thread_metadata(void) { #endif fprintf(output_file, - " {\"ph\": \"M\", \"pid\": %u, \"tid\": %u, \"name\": \"thread_name\", \"args\": {\"name\": \"%lu %s\"}},\n", + " {\"ph\": \"M\", \"pid\": %u, \"tid\": %u, \"name\": \"thread_name\", \"args\": {\"name\": \"%lu %s\"}}\n", process_id, current_thread_serial, native_thread_id, native_thread_name_buffer ); } @@ -106,7 +106,6 @@ static VALUE tracing_start(VALUE _self, VALUE output_path) { started_tracing_at_microseconds = timestamp_microseconds(); process_id = getpid(); - fprintf(output_file, "[\n"); render_event("started_tracing"); current_hook = rb_internal_thread_add_event_hook( @@ -143,7 +142,6 @@ static VALUE tracing_stop(VALUE _self) { gc_tracepoint = Qnil; render_event("stopped_tracing"); - fprintf(output_file, "]\n"); if (fclose(output_file) != 0) rb_syserr_fail(errno, "Failed to close GvlTracing output file"); @@ -158,7 +156,7 @@ static double timestamp_microseconds(void) { return (current_monotonic.tv_nsec / 1000.0) + (current_monotonic.tv_sec * 1000.0 * 1000.0); } -// Render output using trace event format for perfetto: +// Generate a list of trace event with format for perfetto that will be reformated lib/gvl_tracing: // https://chromium.googlesource.com/catapult/+/refs/heads/main/docs/trace-event-format.md static void render_event(const char *event_name) { // Event data @@ -180,9 +178,9 @@ static void render_event(const char *event_name) { fprintf(output_file, // Finish previous duration - " {\"ph\": \"E\", \"pid\": %u, \"tid\": %u, \"ts\": %f},\n" \ + "{\"ph\": \"E\", \"pid\": %u, \"tid\": %u, \"ts\": %f}\n" \ // Current event - " {\"ph\": \"B\", \"pid\": %u, \"tid\": %u, \"ts\": %f, \"name\": \"%s\"},\n", + "{\"ph\": \"B\", \"pid\": %u, \"tid\": %u, \"ts\": %f, \"name\": \"%s\"}\n", // Args for first line process_id, thread_id, now_microseconds, // Args for second line diff --git a/lib/gvl-tracing.rb b/lib/gvl-tracing.rb index 12d561a..0b28712 100644 --- a/lib/gvl-tracing.rb +++ b/lib/gvl-tracing.rb @@ -28,6 +28,50 @@ require_relative "gvl_tracing/version" require "gvl_tracing_native_extension" +require "json" module GvlTracing + class << self + @@path = "/tmp/gvl-tracing.json" + + def start(file) + @@path = file + GvlTracingNativeExtension.start(@@path) + end + + def stop + thread_list = Thread.list + GvlTracingNativeExtension.stop + set_thread_name(thread_list) + end + + private + + def set_thread_name(thread_list) + output_file = File.open(@@path) + output = output_file.read.split("\n").map do |event| + parse_event = JSON.parse(event) + thread_id = parse_event.dig("args", "name") + + next(parse_event) unless thread_id + + thread = thread_list.find { |t| t.native_thread_id.to_s == thread_id.strip } + + next(parse_event) unless thread + + parse_event["args"]["name"] = thread_label(thread) + parse_event + end + File.write(@@path, output.to_json) + end + + REGEX = /lib(?!.*lib)\/([a-zA-Z-]+)/ + def thread_label(thread) + lib_name = thread.to_s.match(REGEX) + + return thread.name if lib_name.nil? + + "#{thread.name} from #{lib_name[1]}" + end + end end