Skip to content

Commit

Permalink
Provide when possible the thread name and gem name
Browse files Browse the repository at this point in the history
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 ivoanjo#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.
  • Loading branch information
benoittgt committed Apr 26, 2023
1 parent 42b14b1 commit a138ec3
Show file tree
Hide file tree
Showing 5 changed files with 71 additions and 10 deletions.
1 change: 1 addition & 0 deletions examples/thread_name_with_extension.json
Original file line number Diff line number Diff line change
@@ -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"}]
18 changes: 18 additions & 0 deletions examples/thread_name_with_extension.rb
Original file line number Diff line number Diff line change
@@ -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
6 changes: 3 additions & 3 deletions ext/gvl_tracing_native_extension/extconf.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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")

Expand Down
12 changes: 5 additions & 7 deletions ext/gvl_tracing_native_extension/gvl_tracing.c
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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
);
}
Expand All @@ -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(
Expand Down Expand Up @@ -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");

Expand All @@ -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
Expand All @@ -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
Expand Down
44 changes: 44 additions & 0 deletions lib/gvl-tracing.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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

0 comments on commit a138ec3

Please sign in to comment.