Provide thread name (and when possible gem name) on output #12

benoittgt · 2023-04-05T19:47:40Z

gvl-tracing handles properly handles thread name for basic usage like:

  Thread.new do
    Thread.current.name = "thread name"
  end

But on more complicated examples with external libraries, it is not able to properly handles thread name.
Jean had a good idea in #9 with using Thread.list.

This commit does this:

Store as list of json line, events we want to monitor
Store Thread.list before stopping gvl tracing
Iterate of events stored in json file and modify entries where we can find the id of a thread
Go a little bit further when we can and provide the gem name related to the thread

This is a very naive approach and probably not super efficient. But this is a first try.

Screenshot with the new examples file:

Screenshot of a gvl-tracing on a Rails app with some multihread:

Opening as a draft because code need probably some rework.

ext/gvl_tracing_native_extension/gvl_tracing.c

lib/gvl-tracing.rb

casperisfine · 2023-04-06T11:13:46Z

lib/gvl-tracing.rb

+
+    REGEX = /lib(?!.*lib)\/([a-zA-Z-]+)/
+    def thread_label(thread)
+      lib_name = thread.to_s.match(REGEX)


If your goal is to exact a gem name or something, then thread.backtrace_locations.last.path might be cleaner.

I look at it a little bit. But bracktrace is an array of strings.
The last element looks very similar to Thread instance to_s

thread.backtrace.last => "/Users/benoit.tigeot/.rbenv/versions/3.2.0/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'"

I was pointing at bracktrace_locations, not backtrace.

Also to avoid allocation too much useless stuff: t.backtrace_locations(1, 1).first.path

I tried an the main issue is we may do not have path.

So diff is

--- a/lib/gvl-tracing.rb +++ b/lib/gvl-tracing.rb @@ -81,7 +81,7 @@ module GvlTracing REGEX = /lib(?!.*lib)\/([a-zA-Z-]+)/ def thread_label(thread) - lib_name = thread.to_s.match(REGEX) + lib_name = thread.backtrace_locations(1, 1).first&.path&.match(REGEX)

Right, could be a native method.

Do you think we should still change it to backtrace_locations? From outside I see limited gains.

I don't have a strong opinion on this one (yet? xD), so let's go with what you picked for now :)

casperisfine · 2023-04-06T11:15:13Z

lib/gvl-tracing.rb

+
+    def aggreate_thread_list(list)
+      list.each_with_object({}) do |t, acc|
+        next unless t.name


Why skip if it doesn't have a name?

The vast majority of threads aren't named. I think a good thing would be to use the name is available, and if not fallback to parsing its backtrace.

The thing that surprise me is that
https://github.com/ivoanjo/gvl-tracing/blob/master/examples/example4.rb#L13
Is properly handled by the C code that look for thread name. But thread list is not able to get it. But in the scenario of the Rails app (like in my initial example), it works properly with Thread.list.

That why I skip Thread without name here. I think your proposal is a good idea, but Thread.list needs to report properly to Thread#name like for example4.

I think you provide the answer bellow, and it is also mentioned in doc.

it may set the name to pthread and/or kernel.

As a note, example4.rb doesn't work with the new code because the threads die before .stop -- thus they won't be in Thread.list by the time we call it.

Maybe when t == Thread.main it's worth printing "Main Thread" or something?

benoittgt · 2023-04-06T12:11:03Z

ext/gvl_tracing_native_extension/gvl_tracing.c

@@ -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",


I am wondering if we still need to provide thread name here.

This is required. For example the example4.rb works with this code. We are not able to get Thread#name via Thread.list

ivoanjo · 2023-04-10T15:31:18Z

Hey there!

Big thanks for working on this 🎉🎉🎉

I was a bit slow to respond over Easter weekend but I'll make an effort to be more responsive to this PR from now on :) :)

I was doing a few experiments with the perfetto UI and I think there's a path to avoiding post-processing the output with the following insight: the perfetto UI doesn't mind where in the event sequence the thread_name appears.

It turns out the metadata event doesn't have to show up when we first see the thread (as I initially implemented). Furthermore, I just experimented a bit and it turns out that if we repeat the metadata events for a thread more than once, and perfetto only displays the last one.

Thus, I think we don't need to do the reparsing; instead, as part of stop, we could re-print the names of the threads to the trace file, e.g. by perhaps building up the thread names in Ruby as you're doing in the PR, and then passing it as a string that gets appended to the trace file before it gets closed. And for perfetto it seems like this is OK -- we don't even need to omit the duplicate names at the beginning.

What do you think? I'm suggesting this approach because it means that even if we run the tracing for a long time, the overhead when stopping would always be O(number of threads) which seems quite reasonable.

There is another downside with this approach of getting the thread names at the end, which I am totally ok with if we don't solve yet -- I didn't solve it in my first implementation either. I'm sharing it here more for discussion :)

The issue is because Ruby reuses native threads, it means that using only the native thread id to identify a thread and match it to a Ruby Thread object may not be enough -- two Ruby Thread objects can actually share the same native thread id.

This means that the name can be completely wrong, if we hit one of these cases :)

casperisfine · 2023-04-11T07:18:35Z

This means that the name can be completely wrong, if we hit one of these cases :)

Yeah, but it's hard to solve this. We'd need a callback on thread start to eagerly assign thread names.

Overall, code that spawn short lived threads are rare, so maybe it's an OK limitation?

ivoanjo · 2023-04-11T07:53:37Z

This means that the name can be completely wrong, if we hit one of these cases :)

Overall, code that spawn short lived threads are rare, so maybe it's an OK limitation?

Definitely it's OK to not solve it in this PR! I brought it up since it would be nice to fix at some point -- as it's a bit of a sharp edge that can confuse users -- and maybe the discussion here would shine a light on what we could do for that one :)

Yeah, but it's hard to solve this. We'd need a callback on thread start to eagerly assign thread names.

I've been wondering if we could approximate it during RUBY_INTERNAL_THREAD_EVENT_READY/RUBY_INTERNAL_THREAD_EVENT_RESUMED/RUBY_INTERNAL_THREAD_EVENT_SUSPENDED by checking if rb_thread_current() is still the last one we saw for this thread. Something like this?

casperisfine · 2023-04-11T09:08:24Z

Something like this?

The problem is that you can only generate the name when you hold the GVL. So you could detect that the name need to be generated again, but couldn't do it from these callbacks (except for RESUMED).

ivoanjo · 2023-04-11T09:51:41Z

The problem is that you can only generate the name when you hold the GVL. So you could detect that the name need to be generated again, but couldn't do it from these callbacks (except for RESUMED).

Right! I guess there's two parts of the problem:

Detecting if it is the same thread, giving it a new "tid" as needed (or current_thread_serial as it's currently called)
Getting the name for a given thread

The name could still come as a best-effort thing done later (as this PR does) -- worst case, we don't get a name.

benoittgt · 2023-04-12T08:08:23Z

Thus, I think we don't need to do the reparsing; instead, as part of stop, we could re-print the names of the threads to the trace file, e.g. by perhaps building up the thread names in Ruby as you're doing in the PR, and then passing it as a string that gets appended to the trace file before it gets closed. And for perfetto it seems like this is OK -- we don't even need to omit the duplicate names at the beginning.

That's interesting. I'm gonna have a look at what is possible with metadatas and perfetto UI.

benoittgt · 2023-04-14T14:58:24Z

@ivoanjo I had a quick look of your proposal and pushed a commit. It is much better. Good catch with perfetto trace format. The only issue I have is the thread_id provided by the C extension is different from the one I get in thread list. I didn't look a it yet.

Edit

Maybe going in this direction may be a good idea? It is working properly. What was the need of using serial instead of a native thread id?

--- a/ext/gvl_tracing_native_extension/gvl_tracing.c
+++ b/ext/gvl_tracing_native_extension/gvl_tracing.c
@@ -76,10 +76,11 @@ static inline void initialize_thread_id(void) {

 static inline void render_thread_metadata(void) {
   uint64_t native_thread_id = 0;
-  #ifdef HAVE_GETTID
-    native_thread_id = gettid();
-  #elif HAVE_PTHREAD_THREADID_NP
+
+  #ifdef HAVE_PTHREAD_THREADID_NP
     pthread_threadid_np(pthread_self(), &native_thread_id);
+  #elif HAVE_GETTID
+    native_thread_id = gettid();
   #else
     native_thread_id = current_thread_serial; // TODO: Better fallback for Windows?
   #endif
@@ -91,9 +92,8 @@ 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",
-    process_id, current_thread_serial, native_thread_id, native_thread_name_buffer
-  );
+    "  {\"ph\": \"M\", \"pid\": %u, \"tid\": %llu, \"name\": \"thread_name\", \"args\": {\"name\": \"%lu %s\"}},\n",
+    process_id, native_thread_id, native_thread_id, native_thread_name_buffer);
 }

 static VALUE tracing_start(VALUE _self, VALUE output_path) {
@@ -170,6 +170,15 @@ static void render_event(const char *event_name) {
   }

   unsigned int thread_id = current_thread_serial;
+  uint64_t native_thread_id = 0;
+
+  #ifdef HAVE_PTHREAD_THREADID_NP
+    pthread_threadid_np(pthread_self(), &native_thread_id);
+  #elif HAVE_GETTID
+    native_thread_id = gettid();
+  #else
+    native_thread_id = current_thread_serial; // TODO: Better fallback for Windows?
+  #endif

   // Each event is converted into two events in the output: one that signals the end of the previous event
   // (whatever it was), and one that signals the start of the actual event we're processing.
@@ -180,13 +189,13 @@ 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\": %llu, \"tid\": %u, \"ts\": %f},\n" \
     // Current event
-    "  {\"ph\": \"B\", \"pid\": %u, \"tid\": %u, \"ts\": %f, \"name\": \"%s\"},\n",
+    "  {\"ph\": \"B\", \"pid\": %llu, \"tid\": %u, \"ts\": %f, \"name\": \"%s\"},\n",
     // Args for first line
-    process_id, thread_id, now_microseconds,
+    process_id, native_thread_id , now_microseconds,
     // Args for second line
-    process_id, thread_id, now_microseconds, event_name
+    process_id, native_thread_id , now_microseconds, event_name
   );
 }

ivoanjo

Ah, yes, the sequential tid! On hindsight, I did totally gloss over that in my suggestion, making it seem easier than it was -- sorry!

You can actually see the story of its introduction in #4 .
TL;DR:

gettid() is not supported on macOS
We discussed replacing it by rb_nativethread_self() but that got us long ids which the perfetto UI didn't like at the time
The sequential id ended up being adopted instead

It was only in a later change that I introduced the pthread_threadid_np for macOS as the tid.

So yes, I think at this point it's perfectly reasonable to switch back to using the thread_id as the tid, instead of the sequential value.

(At some point something like the sequential value may need to make a return to allow distinguishing thread reuse, but let's put that aside for now.)

lib/gvl-tracing.rb

ivoanjo · 2023-04-16T09:28:45Z

lib/gvl-tracing.rb

+      list.each_with_object([]) do |t, acc|
+        next unless t.name
+
+        acc << {"ph": "M", "pid": Process.pid, "tid": t.native_thread_id, "name": "thread_name", "args": {"name": thread_label(t)}}.to_json


Minor: To be honest, this line is so close to the final output JSON, that I'm not sure it's worth using to_json ;)

ivoanjo · 2023-04-16T09:47:45Z

lib/gvl-tracing.rb

+
+    def aggreate_thread_list(list)
+      list.each_with_object({}) do |t, acc|
+        next unless t.name


As a note, example4.rb doesn't work with the new code because the threads die before .stop -- thus they won't be in Thread.list by the time we call it.

benoittgt · 2023-04-24T21:53:02Z

So yes, I think at this point it's perfectly reasonable to switch back to using the thread_id as the tid, instead of the sequential value.

I am wondering if my change properly address your suggestion.

I tested the last code change on macOS with success with example4.rb (we fallback on thread name via native_thread_name_buffer), thread_name_with_extension.rb and Rails app code.

Sorry for the late reply. I was on vacations. 😊

ext/gvl_tracing_native_extension/gvl_tracing.c

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.

To display the proper thread name in some situation we store Thread.list before stoping the profiling and append thread name to the events file for perfetto tool.

Fix type warning

ivoanjo

Great work so far! I've left a bunch more suggestions, but I think after the next round I'll be more than happy to merge and put out a release :)

P.s.: I may be a bit slow to respond on the next few days, taking a bit of time off before RubyKaigi! ;)

ext/gvl_tracing_native_extension/gvl_tracing.c

ivoanjo · 2023-04-27T14:20:51Z

ext/gvl_tracing_native_extension/gvl_tracing.c

  fprintf(output_file,
-    "  {\"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
-  );
+    "  {\"ph\": \"M\", \"pid\": %u, \"tid\": %llu, \"name\": \"thread_name\", \"args\": {\"name\": \"%llu %s\"}},\n",
+    process_id, thread_id, thread_id, native_thread_name_buffer);
 }


The change to use %llu is actually not correct for Linux -- if you look at the CI runs, it complains that it's not correct of a uint64_t. (But it is correct for macOS -- going back to %lu makes the macOS build complain).

I suggest using PRIu64, which should work correctly for both.

I switched to long int. Maybe it's better?

ext/gvl_tracing_native_extension/gvl_tracing.c

ivoanjo · 2023-04-27T14:33:06Z

lib/gvl-tracing.rb

+
+    def aggreate_thread_list(list)
+      list.each_with_object({}) do |t, acc|
+        next unless t.name


Maybe when t == Thread.main it's worth printing "Main Thread" or something?

ivoanjo · 2023-04-27T14:34:25Z

lib/gvl-tracing.rb

+
+    REGEX = /lib(?!.*lib)\/([a-zA-Z-]+)/
+    def thread_label(thread)
+      lib_name = thread.to_s.match(REGEX)


I don't have a strong opinion on this one (yet? xD), so let's go with what you picked for now :)

examples/thread_name_with_extension.rb

ivoanjo · 2023-04-27T14:39:59Z

examples/thread_name_with_extension.json

+  {"ph": "M", "pid": 44888, "tid": 476842, "name": "thread_name", "args": {"name": "476842 "}},
+  {"ph": "E", "pid": 44888, "tid": 476842, "ts": 66.000000},
+  {"ph": "B", "pid": 44888, "tid": 476842, "ts": 66.000000, "name": "started"},
+  {"ph": "E", "pid": 44888, "tid": 476842, "ts": 69.000000},
+  {"ph": "B", "pid": 44888, "tid": 476842, "ts": 69.000000, "name": "wants_gvl"},
+  {"ph": "M", "pid": 44888, "tid": 476843, "name": "thread_name", "args": {"name": "476843 "}},
+  {"ph": "E", "pid": 44888, "tid": 476843, "ts": 82.000000},
+  {"ph": "B", "pid": 44888, "tid": 476843, "ts": 82.000000, "name": "started"},
+  {"ph": "E", "pid": 44888, "tid": 476843, "ts": 85.000000},
+  {"ph": "B", "pid": 44888, "tid": 476843, "ts": 85.000000, "name": "wants_gvl"},
+  {"ph": "M", "pid": 44888, "tid": 476844, "name": "thread_name", "args": {"name": "476844 "}},
+  {"ph": "E", "pid": 44888, "tid": 476844, "ts": 93.000000},
+  {"ph": "B", "pid": 44888, "tid": 476844, "ts": 93.000000, "name": "started"},


Not anything this PR touches or changes, but it's interesting that we're not getting beyond microsecond precision on macOS, but we do so on Linux. At some point I need to perhaps look into the other options beyond CLOCK_MONOTONIC to see if we can make it tighter (I think there's a _RAW variant....)

Interesting.

There is probably a more elegant way of writing it. I had to use two types because `pthread_self` doesn't like a `long int`.

Not visible on MacOS but we have a warning. ../../../../ext/gvl_tracing_native_extension/gvl_tracing.c:153:17: warning: old-style function definition [-Wold-style-definition] 153 | static uint64_t native_thread_id() { | ^~~~~~~~~~~~~~~~

benoittgt · 2023-04-27T15:58:25Z

Thanks @ivoanjo for your review. Here is few screenshots of the new output. I have similar output on a debian 11 too.

I am not sure for the C changes. You will tell me. :)

ivoanjo · 2023-06-06T20:10:17Z

This looks great! I hope you don't take my long delay the wrong way -- I definitely I am very grateful for the contribution. It's just been an intense few weeks :)

And feel free to send more things this way :)

ivoanjo · 2023-06-06T21:10:41Z

@benoittgt I've just released this improvement as version 1.2.0 on rubygems 🎉

casperisfine reviewed Apr 5, 2023

View reviewed changes

ext/gvl_tracing_native_extension/gvl_tracing.c Outdated Show resolved Hide resolved

casperisfine reviewed Apr 5, 2023

View reviewed changes

lib/gvl-tracing.rb Outdated Show resolved Hide resolved

lib/gvl-tracing.rb Outdated Show resolved Hide resolved

benoittgt requested a review from casperisfine April 6, 2023 10:28

casperisfine reviewed Apr 6, 2023

View reviewed changes

benoittgt commented Apr 6, 2023

View reviewed changes

benoittgt marked this pull request as ready for review April 6, 2023 13:44

benoittgt force-pushed the provide-thread-name branch 3 times, most recently from d391de4 to 64494bd Compare April 6, 2023 15:44

ivoanjo mentioned this pull request Apr 10, 2023

Feature/improvement brainstorming #13

Open

benoittgt force-pushed the provide-thread-name branch 2 times, most recently from df185f0 to 7b079a0 Compare April 14, 2023 14:55

ivoanjo reviewed Apr 16, 2023

View reviewed changes

benoittgt commented Apr 24, 2023

View reviewed changes

ext/gvl_tracing_native_extension/gvl_tracing.c Show resolved Hide resolved

benoittgt force-pushed the provide-thread-name branch from 647f086 to 7c4ae7c Compare April 26, 2023 15:15

benoittgt added 7 commits April 26, 2023 17:15

No need to define new Module name + reject Thread without name

46a37f6

Construct thread list before to only have to do direct hash access

bcccdc0

Make method from C extension private

238319e

Provide similar path as other examples

1ad9ba8

Append thread name to the end of the output file

793a6fd

To display the proper thread name in some situation we store Thread.list before stoping the profiling and append thread name to the events file for perfetto tool.

Use in priority PTHREADID to better match name via thread list

b8a1109

benoittgt added 3 commits April 26, 2023 17:15

Maintain a fallback for thread that stop too early

75dd210

Fix type warning

Avoid duplication in C code when fetching thread_id

2dfb68d

Keep indentation and update example for thread_name_with_extension

c1baf71

benoittgt force-pushed the provide-thread-name branch from 7c4ae7c to c1baf71 Compare April 26, 2023 15:15

ivoanjo reviewed Apr 27, 2023

View reviewed changes

benoittgt added 8 commits April 27, 2023 17:57

Avoid overhead on each event emission

33880dd

There is probably a more elegant way of writing it. I had to use two types because `pthread_self` doesn't like a `long int`.

Make it clearer about why we do not properly close the json file

bfa470f

Remove one warning

7b7b3b1

Not visible on MacOS but we have a warning. ../../../../ext/gvl_tracing_native_extension/gvl_tracing.c:153:17: warning: old-style function definition [-Wold-style-definition] 153 | static uint64_t native_thread_id() { | ^~~~~~~~~~~~~~~~

Proper ruby method name

aa699c5

Avoid duplication of thread id in perfetto UI

e53151c

Print info when it is the main thread instead of an empty string

f18abce

Typo

6a166c0

Regenerate examples

536d492

ivoanjo merged commit 2ca630f into ivoanjo:master Jun 6, 2023

This was referenced Jun 6, 2023

Add support for passing a block to start method #14

Merged

Map native thread ids with Ruby thread names? #9

Closed

benoittgt deleted the provide-thread-name branch June 21, 2023 14:43

Provide thread name (and when possible gem name) on output #12

Provide thread name (and when possible gem name) on output #12

Conversation

benoittgt commented Apr 5, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benoittgt Apr 6, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benoittgt Apr 6, 2023 • edited Loading

Choose a reason for hiding this comment

ivoanjo commented Apr 10, 2023 • edited Loading

casperisfine commented Apr 11, 2023

ivoanjo commented Apr 11, 2023

casperisfine commented Apr 11, 2023

ivoanjo commented Apr 11, 2023

benoittgt commented Apr 12, 2023

benoittgt commented Apr 14, 2023 • edited Loading

Edit

ivoanjo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benoittgt commented Apr 24, 2023 • edited Loading

ivoanjo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benoittgt commented Apr 27, 2023 • edited Loading

ivoanjo commented Jun 6, 2023

ivoanjo commented Jun 6, 2023

benoittgt commented Apr 5, 2023 •

edited

Loading

benoittgt Apr 6, 2023 •

edited

Loading

benoittgt Apr 6, 2023 •

edited

Loading

ivoanjo commented Apr 10, 2023 •

edited

Loading

benoittgt commented Apr 14, 2023 •

edited

Loading

benoittgt commented Apr 24, 2023 •

edited

Loading

benoittgt commented Apr 27, 2023 •

edited

Loading