eBPF-based timeline visualization tool (#17190)

Merged-By: peterzhu2118 <peter@peterzhu.ca>

depend

@@ -18642,6 +18642,8 @@ thread.$(OBJEXT): {$(VPATH)}onigmo.h
 thread.$(OBJEXT): {$(VPATH)}oniguruma.h
 thread.$(OBJEXT): {$(VPATH)}prism_compile.h
 thread.$(OBJEXT): {$(VPATH)}prism_xallocator.h
+thread.$(OBJEXT): {$(VPATH)}probes.dmyh
+thread.$(OBJEXT): {$(VPATH)}probes.h
 thread.$(OBJEXT): {$(VPATH)}ractor.h
 thread.$(OBJEXT): {$(VPATH)}ractor_core.h
 thread.$(OBJEXT): {$(VPATH)}ruby_assert.h
@@ -20710,6 +20712,8 @@ vm_sync.$(OBJEXT): {$(VPATH)}missing.h
 vm_sync.$(OBJEXT): {$(VPATH)}node.h
 vm_sync.$(OBJEXT): {$(VPATH)}onigmo.h
 vm_sync.$(OBJEXT): {$(VPATH)}oniguruma.h
+vm_sync.$(OBJEXT): {$(VPATH)}probes.dmyh
+vm_sync.$(OBJEXT): {$(VPATH)}probes.h
 vm_sync.$(OBJEXT): {$(VPATH)}ractor.h
 vm_sync.$(OBJEXT): {$(VPATH)}ractor_core.h
 vm_sync.$(OBJEXT): {$(VPATH)}ruby_assert.h

gc.c

@@ -1054,6 +1054,10 @@ rb_newobj(rb_execution_context_t *ec, VALUE klass, VALUE flags, shape_id_t shape
         gc_newobj_hook(obj);
     }
 
+    if (RUBY_DTRACE_GC_OBJ_NEW_ENABLED()) {
+        RUBY_DTRACE_GC_OBJ_NEW((void*)obj, flags);
+    }
+
 #if RGENGC_CHECK_MODE
 # ifndef GC_DEBUG_SLOT_FILL_SPECIAL_VALUE
 #  define GC_DEBUG_SLOT_FILL_SPECIAL_VALUE 255
@@ -1539,7 +1543,13 @@ rb_gc_obj_free(void *objspace, VALUE obj)
 
     RB_DEBUG_COUNTER_INC(obj_free);
 
-    switch (BUILTIN_TYPE(obj)) {
+    enum ruby_value_type builtin_type = BUILTIN_TYPE(obj);
+
+    if (RUBY_DTRACE_GC_OBJ_FREE_ENABLED()) {
+        RUBY_DTRACE_GC_OBJ_FREE((void*)obj, RBASIC(obj)->flags);
+    }
+
+    switch (builtin_type) {
       case T_NIL:
       case T_FIXNUM:
       case T_TRUE:
@@ -1550,7 +1560,7 @@ rb_gc_obj_free(void *objspace, VALUE obj)
         break;
     }
 
-    switch (BUILTIN_TYPE(obj)) {
+    switch (builtin_type) {
       case T_OBJECT:
         if (FL_TEST_RAW(obj, ROBJECT_HEAP)) {
             if (rb_obj_shape_complex_p(obj)) {
@@ -5435,6 +5445,10 @@ static void *ruby_xmalloc_body(size_t size);
 void *
 ruby_xmalloc(size_t size)
 {
+    if (RUBY_DTRACE_GC_XMALLOC_ENABLED()) {
+        RUBY_DTRACE_GC_XMALLOC(1, size);
+    }
+
     return handle_malloc_failure(ruby_xmalloc_body(size));
 }
 
@@ -5477,6 +5491,10 @@ static void *ruby_xmalloc2_body(size_t n, size_t size);
 void *
 ruby_xmalloc2(size_t n, size_t size)
 {
+    if (RUBY_DTRACE_GC_XMALLOC_ENABLED()) {
+        RUBY_DTRACE_GC_XMALLOC(n, size);
+    }
+
     return handle_malloc_failure(ruby_xmalloc2_body(n, size));
 }
 
@@ -5491,6 +5509,10 @@ static void *ruby_xcalloc_body(size_t n, size_t size);
 void *
 ruby_xcalloc(size_t n, size_t size)
 {
+    if (RUBY_DTRACE_GC_XCALLOC_ENABLED()) {
+        RUBY_DTRACE_GC_XCALLOC(n, size);
+    }
+
     return handle_malloc_failure(ruby_xcalloc_body(n, size));
 }
 
@@ -5554,9 +5576,20 @@ ruby_xrealloc2(void *ptr, size_t n, size_t size)
 #ifdef ruby_xfree_sized
 #undef ruby_xfree_sized
 #endif
+
+static bool g_nofree = false;
+
 void
 ruby_xfree_sized(void *x, size_t size)
 {
+    if (g_nofree) {
+        return;
+    }
+
+    if (RUBY_DTRACE_GC_XFREE_ENABLED()) {
+        RUBY_DTRACE_GC_XFREE(x, size);
+    }
+
     if (LIKELY(x)) {
         /* It's possible for a C extension's pthread destructor function set by pthread_key_create
          * to be called after ruby_vm_destruct and attempt to free memory. Fall back to mimfree in
@@ -5820,6 +5853,12 @@ rb_gc_checking_shareable(void)
 void
 Init_GC(void)
 {
+    const char* nofree_str = getenv("RUBY_NO_FREE");
+    if (nofree_str && strcmp(nofree_str, "yes") == 0) {
+        fprintf(stderr, "WARNING: Enabling no-free mode! xfree() will never free anything!\n");
+        g_nofree = true;
+    }
+
 #undef rb_intern
     rb_gc_register_address(&id2ref_value);
 

gc/default/default.c

@@ -74,6 +74,9 @@ rb_hrtime_sub(rb_hrtime_t a, rb_hrtime_t b)
 
 #include "probes.h"
 
+#define RUBY_DTRACE_GC_HOOK(name, ...) \
+    do {if (RUBY_DTRACE_GC_##name##_ENABLED()) RUBY_DTRACE_GC_##name(__VA_ARGS__);} while (0)
+
 #if USE_ZJIT
 # include "gc/default/zjit_fastpath.h"
 #endif
@@ -4414,6 +4417,8 @@ gc_sweep_step(rb_objspace_t *objspace, rb_heap_t *heap)
         gc_sweep_page(objspace, heap, &ctx);
         int free_slots = ctx.freed_slots + ctx.empty_slots;
 
+        RUBY_DTRACE_GC_HOOK(SWEEP_PAGE, ctx.page->slot_size, ctx.final_slots, ctx.freed_slots, ctx.empty_slots);
+
         heap->sweeping_page = ccan_list_next(&heap->pages, sweep_page, page_node);
 
         if (free_slots == sweep_page->total_slots) {
@@ -5175,12 +5180,13 @@ gc_mark_stacked_objects(rb_objspace_t *objspace, int incremental, size_t count)
         }
         gc_mark_children(objspace, obj);
 
+        popped_count++;
+
         if (incremental) {
             if (RGENGC_CHECK_MODE && !RVALUE_MARKING(objspace, obj)) {
                 rb_bug("gc_mark_stacked_objects: incremental, but marking bit is 0");
             }
             CLEAR_IN_BITMAP(GET_HEAP_MARKING_BITS(obj), obj);
-            popped_count++;
 
             if (popped_count + (objspace->marked_slots - marked_slots_at_the_beginning) > count) {
                 break;
@@ -5191,6 +5197,8 @@ gc_mark_stacked_objects(rb_objspace_t *objspace, int incremental, size_t count)
         }
     }
 
+    RUBY_DTRACE_GC_HOOK(MARK_STACKED_OBJECTS, popped_count);
+
     if (RGENGC_CHECK_MODE >= 3) gc_verify_internal_consistency(objspace);
 
     if (is_mark_stack_empty(mstack)) {
@@ -7247,6 +7255,8 @@ gc_enter(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_
 {
     *lock_lev = RB_GC_VM_LOCK();
 
+    RUBY_DTRACE_GC_HOOK(ENTER, event);
+
     if (objspace->profile.run) {
         switch (event) {
           case gc_enter_event_start:
@@ -7294,6 +7304,8 @@ gc_exit(rb_objspace_t *objspace, enum gc_enter_event event, unsigned int *lock_l
 {
     GC_ASSERT(during_gc != 0);
 
+    RUBY_DTRACE_GC_HOOK(EXIT, event);
+
     rb_gc_event_hook(0, RUBY_INTERNAL_EVENT_GC_EXIT);
 
     if (objspace->profile.gc_pause_start_time) {
@@ -9300,9 +9312,6 @@ gc_prof_timer_stop(rb_objspace_t *objspace)
     }
 }
 
-#define RUBY_DTRACE_GC_HOOK(name) \
-    do {if (RUBY_DTRACE_GC_##name##_ENABLED()) RUBY_DTRACE_GC_##name();} while (0)
-
 static inline void
 gc_prof_mark_timer_start(rb_objspace_t *objspace)
 {

probes.d

@@ -214,6 +214,123 @@ provider ruby {
      Fired at the end of a sweep phase.
   */
   probe gc__sweep__end();
+
+  /*
+     ruby:::gc-enter(event);
+
+     Fired when the `gc_enter` function in default.c is called.
+
+     * `event` the `event` argument passed to gc_enter
+  */
+  probe gc__enter(int event);
+
+  /*
+     ruby:::gc-exit(event);
+
+     Fired when the `gc_exit` function in default.c is called.
+
+     * `event` the `event` argument passed to gc_exit
+  */
+  probe gc__exit(int event);
+
+  /*
+     ruby:::gc-mark-stacked-objects(popped_count);
+
+     Fired for every invocation of `gc_mark_stacked_objects` in default.c.
+
+     * `popped_count` the number of objects popped from the mark stack in that invocation
+  */
+  probe gc__mark_stacked_objects(int popped_count);
+
+  /*
+     ruby:::gc-sweep_page(slot_size, final_slots, freed_slots, empty_slots);
+
+     Fired for every page swept in `gc_sweep_step` in default.c.
+
+     * `slot_size` is the slot size of the page.
+     * Other arguments are from the `gc_sweep_context` struct.
+  */
+  probe gc__sweep_page(int slot_size, int final_slots, int freed_slots, int empty_slots);
+
+  /*
+     ruby:::gc-obj_new();
+
+     Fired when an object is allocated
+
+     * `obj` the pointer to the allocated object
+     * `flags` the initial flags of the object
+  */
+  probe gc__obj_new(void *obj, int flags);
+
+  /*
+     ruby:::gc-obj_free();
+
+     Fired when finalizing an object with `rb_gc_obj_free`.
+
+     * `obj` the pointer to the finalized object
+     * `flags` the flags of the object when it is finalized
+  */
+  probe gc__obj_free(void *obj, int flags);
+
+  /*
+     ruby:::gc-xmalloc(n, size);
+
+     Fired when allocating memory with `ruby_xmalloc` or `ruby_xmalloc2`.
+
+     * `n` the number of elements.  For `ruby_xmalloc` it is 1.
+     * `size` the size of each element
+  */
+  probe gc__xmalloc(int n, int size);
+
+  /*
+     ruby:::gc-xcalloc();
+
+     Fired when allocating memory with `ruby_xcalloc`.
+
+     * `n` the number of elements.  For `ruby_xmalloc` it is 1.
+     * `size` the size of each element
+  */
+  probe gc__xcalloc(int n, int size);
+
+  /*
+     ruby:::gc-xfree(ptr, size);
+
+     Fired when de-allocating memory with `ruby_xfree` or `ruby_xfree_sized`.
+
+     * `ptr` the pointer to the object
+     * `size` the size of the object.  0 if called with `xfree`
+  */
+  probe gc__xfree(void *obj, int size);
+
+  /*
+     ruby:::gvl-acquire();
+
+     Fired the global VM lock is acquired
+  */
+  probe gvl__acquire();
+
+  /*
+     ruby:::gvl-release();
+
+     Fired the global VM lock is release
+  */
+  probe gvl__release();
+
+  /*
+     ruby:::rts-set_running();
+
+     Fired when setting the running thread of a Ractor (`rb_thread_sched::running`).
+
+     This probe is mainly used to identify the duration in which a thread occupies a Ractor. If the
+     `old_thread` is NULL and the `new_thread` is not NULL, it means the `new_thread` is scheduled
+     onto a Ractor.  If the `old_thread` is not NULL but the `new_thread` is NULL, it means the
+     `old_thread` is de-scheduled form a Ractor.
+
+     * `sched` the `rb_thread_sched` instance
+     * `old_thread` the old thread running on the ractor
+     * `new_thread` the new thread running on the ractor
+  */
+  probe rts__set_running(void *sched, void *old_thread, void *new_thread);
 };
 
 #pragma D attributes Stable/Evolving/Common provider ruby provider

thread_pthread.c

@@ -40,6 +40,8 @@
 #include <time.h>
 #include <signal.h>
 
+#include "probes.h"
+
 #if defined __APPLE__
 # include <AvailabilityMacros.h>
 #endif
@@ -689,6 +691,11 @@ thread_sched_set_running(struct rb_thread_sched *sched, rb_thread_t *th)
     RUBY_DEBUG_LOG("th:%u->th:%u", rb_th_serial(sched->running), rb_th_serial(th));
     VM_ASSERT(sched->running != th);
 
+    if (RUBY_DTRACE_RTS_SET_RUNNING_ENABLED()) {
+        rb_thread_t *old = sched->running;
+        RUBY_DTRACE_RTS_SET_RUNNING(sched, old, th);
+    }
+
     sched->running = th;
 }
 

tool/timeline/README.md

@@ -0,0 +1,214 @@
+# eBPF-based timeline visualization tool
+
+This directory contains timeline visualization tool based on [eBPF] and [bpftrace].  It sets up
+probes that attach to the Userspace Statically Defined Tracepoints (USDT) in the Ruby executable or
+library, records events during the execution of a Ruby program, and outputs a log file in the [Trace
+Event Format] which can be visualized on a timeline in the [Perfetto UI] web frontend.
+
+This tool is primarily intended for analyzing garbage collection performance, but it can also
+visualize other events, such as the acquisition of the global VM lock, and can be extended.
+
+[eBPF]: https://ebpf.io/what-is-ebpf/
+[bpftrace]: https://bpftrace.org/
+[Trace Event Format]: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit?usp=sharing
+[Perfetto UI]: https://www.ui.perfetto.dev/
+
+## How to use?
+
+### Prepare and build
+
+You need to run the tool on a Linux distribution, and you need the following command line tools.
+
+-   `bpftrace`: The `capture.rb` script uses `bpftrace` to capture events.
+-   `dtrace` from [SystemTap]: CRuby uses the `dtrace` command line tool during build time to
+    generate USDT trace points.  Because `bpftrace` can only work with SystemTap's USDT format, you
+    need to install the `dtrace` command line tool from SystemTap, not the [`dtrace` tool from
+    Oracle][dtrace-oracle]
+
+    CAUTION: Ubuntu 26.04 provides both the `dtrace` from SystemTap (package name is
+    `systemtap-sdt-dev`) and the `dtrace` from Oracle (package name is `dtrace`), and they can
+    coexist (installed as `/usr/bin/dtrace` and `/usr/sbin/dtrace`, respectively). Make sure CRuby
+    is using the one from SystemTap.
+
+[SystemTap]: https://sourceware.org/systemtap/
+[dtrace-oracle]: https://github.com/oracle/dtrace
+
+On Ubuntu, you can use the following commands:
+
+```shell
+sudo apt install bpftrace systemtap-sdt-dev
+sudo apt remove dtrace
+```
+
+Build the `ruby` executable.  Make sure the `ruby` executable is built with USDT trace points.  If
+the `configure` command detectes the `dtrace` command line tool, it should be enabled by default. If
+not, add `--with-dtrace` to the `configure` command.  You can use the `readelf -n` command to check
+if the trace points exist. It should show `stapstd` entries with `Provider: ruby`.
+
+```shell
+$ readelf -n /path/to/ruby
+Displaying notes found in: .note.stapsdt
+  Owner                Data size        Description
+  stapsdt              0x00000045       NT_STAPSDT (SystemTap probe descriptors)
+    Provider: ruby
+    Name: array__create
+    Location: 0x000000000006ba92, Base: 0x00000000007abe48, Semaphore: 0x000000000090a658
+    Arguments: -4@$0 8@-16(%rbp) -4@%eax
+...
+```
+
+### Capture and visualize
+
+Open one terminal and run
+
+```shell
+/path/to/capture.rb -r /path/to/ruby
+```
+
+The `-r` option points to the `ruby` executable.  You will be prompted to enter the sudo password.
+Then you will see output on the terminal:
+
+```
+Attaching 'begin' probe
+Trying to attach probe: usdt:/path/to/ruby:ruby:gc__exit
+Trying to attach probe: usdt:/path/to/ruby:ruby:gc__enter
+Trying to attach probe: usdt:/path/to/ruby:ruby:gc__sweep__end
+Trying to attach probe: usdt:/path/to/ruby:ruby:gc__sweep__begin
+Trying to attach probe: usdt:/path/to/ruby:ruby:gc__mark__end
+Trying to attach probe: usdt:/path/to/ruby:ruby:gc__mark__begin
+Attached 7 probes
+====RUBY_TRACING_LOG_START====
+```
+
+Then open another terminal and run a Ruby program using *the same* `ruby` executable specified
+above.  Be careful if you have multiple Ruby builds in your filesystem.
+
+```shell
+/path/to/ruby some_script.rb
+```
+
+Go back to the first terminal.  If everything goes well, you should see output from `capture.rb` in
+the CSV format like this:
+
+```
+...
+GCEnterExit,B,18498,2093498438581,1
+gc_sweep,B,18498,2093498439826
+gc_sweep,E,18498,2093498444465
+GCEnterExit,E,18498,2093498445798,1
+GCEnterExit,B,18498,2093498629067,1
+gc_sweep,B,18498,2093498630379
+gc_sweep,E,18498,2093498682380
+GCEnterExit,E,18498,2093498683848,1
+GCEnterExit,B,18498,2093501215787,3
+GCEnterExit,E,18498,2093501641157,3
+```
+
+Then press CTRL+C to interrupt the `capture.rb` script.  (More precisely, it interrupts the
+underlying `bpftrace` program which `capture.rb` invoked.)
+
+If everything went as expected, we repeat the `capture.rb`, but pipe the output into a log file.
+
+```shell
+/path/to/capture.rb -r /path/to/ruby > running_some_script.log
+```
+
+Then use the other terminal to run the script again
+
+```shell
+/path/to/ruby some_script.rb
+```
+
+Go back to the first terminal and use CTRL+C to interrupt `capture.rb`.  You should see the standard
+output captured in the `running_some_script.log` file.
+
+Then use the `visualize.rb` script to convert the log file into a JSON file.
+
+```shell
+/path/to/visualize.rb running_some_script.log
+```
+
+It should generate a file named `running_some_script.log.json.gz`.
+
+Open a browser and go to <https://www.ui.perfetto.dev/>.  Click "open trace file" and select the
+`running_some_script.log.json.gz` file.  Then you will be able to see the timeline.  Duration
+events, such as `GCEnterExit`, `gc_mark` and `gc_sweep`, are displayed as bars, and instant events
+are displayed as arrows.  Some events, such as `GCEnterExit` and `gc_mark`, have arguments.  If you
+click an event, the arguments will be shown on the bottom part of the window.
+
+### Enabling additional probes
+
+The supported USDT trace points are organized into groups, and the default group is enabled by
+default.  To enable additional groups of trace points, use the `-g` option of `capture.rb`.  For
+example, if you want to monitor the number of objects swept during sweeping, you can enable the
+`sweep_details` group.
+
+```shell
+/path/to/capture.rb -r /path/to/ruby -g sweep_details > running_some_script_with_sweep_details.log
+```
+
+There is no additional options needed for the `visualize.rb` script.  Just run it as usual.
+
+See `lib/tracepoint_defs.rb` for a complete list of groups and their trace points.
+
+### Working with GC modules
+
+The default GC in CRuby can be compiled as a GC module.  If DTrace support is enabled when building
+`ruby`, the USDT trace points will be automatically built into the GC module of the default GC.
+
+When capturing, add the `-m` option to specify the path of the GC module.
+
+```shell
+/path/to/capture.rb -r /path/to/ruby -m /path/to/librubygc.default.so > running_some_script.log
+```
+
+Then run `ruby` with the GC module.
+
+```shell
+RUBY_GC_LIBRARY=default /path/to/ruby some_script.rb
+```
+
+Then visualize in the usual way.
+
+## How to extend?
+
+You can introduce more trace points by editing the `probes.d` file.
+
+Then you can insert the trace points into the program in the form of
+
+```c
+RUBY_DTRACE_XXX_XXX_XXX(/* parameters */)
+```
+
+To capture and visualize those events, you need to edit the script `lib/tracepoint_defs.rb`.  It
+will be read by both the `capture.rb` and the `visualize.rb` scripts.  After adding the definition
+of your added trace points, the events and the arguments will be displayed on the timeline.
+
+In rare cases, you can hack `visualize.rb` directly to do post-processing on each event.  For
+example, you can combine the numbers of objects marked in multiple invocations of
+`gc_mark_stacked_objects` and add it as one argument of the currnet `GCEnterExit` event in the
+timeline.
+
+### Performance concerns
+
+USDT trace points are no-op instructions and have negligible overhead when not attached.  Therefore,
+it is safe to insert the trace points even in the hot paths of hot functions.
+
+However, when a trace point is attached by `bpftrace` (and therefore our capturing tool), it will
+introduce an overhead whenever it is fired.  Different trace points are also fired at different
+frequencies.  For example, `gc_enter` and `gc_exit` events are much less frequent than `obj_new` and
+`obj_free`.  So you should avoid enabling high-frequency trace points which you are not interested
+in in order not to reduce the fidelity of the measurement.  You can do this by grouping the trace
+points by freqneucy in `lib/tracepoint_defs.rb` so that you can selectively enable the trace points
+you are interested in with the `-g` option of `capture.rb`.
+
+## Acknowledgement
+
+This timeline tracing tool is inspired by [a similar tracing tool][mmtk-timeline] from the [Memory
+Management Toolkit (MMTK)][mmtk] project.  The methodology was developed by Claire Huang, Steve
+Blackburn, and Zixian Cai, and is described in details in the paper *[Improving Garbage Collection
+Observability with Performance Tracing][HBC23]*.
+
+[mmtk-timeline]: https://github.com/mmtk/mmtk-core/tree/master/tools/tracing/timeline
+[mmtk]: https://www.mmtk.io/
+[HBC23]: https://doi.org/10.1145/3617651.3622986

tool/timeline/capture.bt

@@ -0,0 +1,9 @@
+BEGIN {
+    printf("====RUBY_TRACING_LOG_START====\n");
+}
+
+% usdt_entries.each do |entry|
+usdt:<%=entry.file%>:ruby:<%=entry.probe_name%> {
+    printf("<%=entry.probe_name%>,%d,%d,%lu<%=",%lu"*entry.nargs%>\n", pid, tid, nsecs<%=(0...entry.nargs).map{|i| ", arg#{i}"}.join%>);
+}
+% end

tool/timeline/capture.rb

@@ -0,0 +1,119 @@
+#!/usr/bin/env ruby
+# frozen_string_literal: true
+
+require 'erb'
+require 'optparse'
+require 'pathname'
+
+require_relative 'lib/tracepoint_defs'
+
+EXTRA_GROUPS = RubyTimelineTool::USDT_DEFS.keys - RubyTimelineTool::DEFAULT_GROUPS
+
+options = {}
+
+OptionParser.new do |parser|
+  parser.accept(Pathname) do |value|
+    Pathname.new(value)
+  end
+  parser.on('-r', '--ruby-bin RUBY', Pathname, 'Path to the ruby executable')
+  parser.on('-m', '--gc-module-so GC_MODULE', Pathname, 'Path to the GC module .so')
+  parser.on('-e', '--erb-debug', TrueClass, 'Print the Ruby script generated by ERB.  For debugging.')
+  parser.on('-p', '--print-script', TrueClass, 'Print the content of the bpftrace script')
+  parser.on('-d', '--dry-run', TrueClass, 'Dry run.  Print the bpftrace command to be executed, but do not actually execute it.')
+  parser.on('-g', '--extra-groups=', "Enable extra USDT groups, separated by comma.  Available groups: #{EXTRA_GROUPS.join(', ')}")
+end.parse!(into: options)
+
+[:'ruby-bin'].each do |k|
+  if !options.include?(k)
+    raise "Option --#{k} is required"
+  end
+end
+
+ruby_bin = options[:'ruby-bin']
+if !ruby_bin.file?
+  raise "Ruby executable '#{ruby_bin}' does not exist"
+end
+
+gc_module_so = options[:'gc-module-so']
+
+gc_module_kind = case
+when gc_module_so.nil?
+  nil
+when m = /librubygc\.(\w+)/.match(gc_module_so.basename.to_s)
+  m[1]
+else
+  raise "Unexpected gc module so name: #{gc_module_so}"
+end
+
+script_path = Pathname(__dir__) / 'capture.bt'
+script = File.read(script_path)
+template = ERB.new(script, trim_mode: '%<>')
+template.location = [script_path.to_s, 1]
+
+if options[:'erb-debug']
+  $stderr.puts template.src
+end
+
+extra_groups_opt = options[:'extra-groups']
+
+selected_groups = RubyTimelineTool::DEFAULT_GROUPS.dup
+
+if !extra_groups_opt.nil?
+  extra_groups_opt.split(',').each do |group|
+    if !EXTRA_GROUPS.include?(group)
+      raise "Unknown USDT group #{group}"
+    end
+
+    selected_groups << group
+  end
+end
+
+selected_groups.uniq!
+
+$stderr.puts "Selected groups: #{selected_groups.join(',')}"
+
+usdts = RubyTimelineTool::USDT_DEFS.values_at(*selected_groups).flatten
+
+ScriptUsdtEntry = Struct.new('ScriptUsdtEntry', :file, :probe_name, :nargs)
+
+usdt_entries = []
+
+usdts.each do |t|
+  file = case [gc_module_kind, t.where]
+    in nil,   'ruby'                  then ruby_bin
+    in nil,   'default'               then ruby_bin
+    in x,     'ruby'                  then ruby_bin
+    in x,     y           if x == y   then gc_module_so
+    else                                   nil
+  end
+
+  if file.nil?
+    @stderr.puts "Skipped probe '#{probe_name}' which is for '#{location}'.  Current GC module: '#{gc_module_kind}'."
+    next
+  end
+
+  nargs = t.args.length
+
+  usdt_entries << ScriptUsdtEntry.new(file, t.probe_name, nargs)
+end
+
+content = template.result_with_hash({
+  usdt_entries:,
+})
+
+if options[:'print-script']
+  $stderr.puts content
+end
+
+IO.write('capture.out.bt', content)
+
+command_line = ['sudo', 'bpftrace', '-v', '--unsafe', 'capture.out.bt']
+$stderr.puts 'Command to execute:'
+$stderr.puts command_line.map { |s| "'#{s}'" }.join(' ')
+
+if options[:'dry-run']
+  $stderr.puts 'Dry run.  Exit...'
+  exit 0
+end
+
+exec(*command_line)

tool/timeline/lib/converter.rb

@@ -0,0 +1,58 @@
+# frozen_string_literal: true
+
+module RubyTimelineTool
+  class Converter
+    def convert_arg(_raw_value)
+      raise 'Not implemented'
+    end
+  end
+
+  class EnumConverter < Converter
+    def initialize(hash)
+      super()
+      @hash = hash
+      @ihash = hash.invert
+    end
+
+    def convert_arg(raw_value)
+      value = raw_value.to_i
+      @ihash[value]
+    end
+
+    def [](key)
+      @hash[key]
+    end
+  end
+
+  class FlagsConverter < Converter
+    def initialize(hash)
+      super()
+      @hash = hash
+    end
+
+    def convert_arg(raw_value)
+      value = raw_value.to_i
+      # Output {foo: true, bar: false, ...}
+      @hash.transform_values do |bit_value|
+        (value & bit_value) != 0
+      end
+    end
+
+    def [](key)
+      @hash[key]
+    end
+  end
+
+  def self.convert_arg(raw_value, converter)
+    case
+    when converter.is_a?(Converter)
+      converter.convert_arg(raw_value)
+    when converter.is_a?(Symbol)
+      raw_value.send(converter)
+    when converter.respond_to?(:call)
+      converter.call(raw_value)
+    else
+      raise "Unexpected converter #{@converter.inspect}"
+    end
+  end
+end

tool/timeline/lib/converter_defs.rb

@@ -0,0 +1,133 @@
+# frozen_string_literal: true
+
+require_relative 'converter'
+
+module RubyTimelineTool
+  # Keep in sync with `enum gc_enter_event` in `gc/default/default.c`.
+  GCEnterEvent = EnumConverter.new({
+    start:      0,
+    continue:   1,
+    rest:       2,
+    finalizer:  3,
+  })
+
+  # Keep in sync with `enum ruby_value_type` in `include/ruby/internal/value_type.h`.
+  RubyBuiltinType = EnumConverter.new({
+    RUBY_T_NONE:      0x00, # /**< Non-object (swept etc.) */:
+    RUBY_T_OBJECT:    0x01, # /**< @see struct ::RObject */
+    RUBY_T_CLASS:     0x02, # /**< @see struct ::RClass and ::rb_cClass */
+    RUBY_T_MODULE:    0x03, # /**< @see struct ::RClass and ::rb_cModule */
+    RUBY_T_FLOAT:     0x04, # /**< @see struct ::RFloat */
+    RUBY_T_STRING:    0x05, # /**< @see struct ::RString */
+    RUBY_T_REGEXP:    0x06, # /**< @see struct ::RRegexp */
+    RUBY_T_ARRAY:     0x07, # /**< @see struct ::RArray */
+    RUBY_T_HASH:      0x08, # /**< @see struct ::RHash */
+    RUBY_T_STRUCT:    0x09, # /**< @see struct ::RStruct */
+    RUBY_T_BIGNUM:    0x0a, # /**< @see struct ::RBignum */
+    RUBY_T_FILE:      0x0b, # /**< @see struct ::RFile */
+    RUBY_T_DATA:      0x0c, # /**< @see struct ::RTypedData */
+    RUBY_T_MATCH:     0x0d, # /**< @see struct ::RMatch */
+    RUBY_T_COMPLEX:   0x0e, # /**< @see struct ::RComplex */
+    RUBY_T_RATIONAL:  0x0f, # /**< @see struct ::RRational */:
+    RUBY_T_NIL:       0x11, # /**< @see ::RUBY_Qnil */
+    RUBY_T_TRUE:      0x12, # /**< @see ::RUBY_Qtrue */
+    RUBY_T_FALSE:     0x13, # /**< @see ::RUBY_Qfalse */
+    RUBY_T_SYMBOL:    0x14, # /**< @see struct ::RSymbol */
+    RUBY_T_FIXNUM:    0x15, # /**< Integers formerly known as Fixnums. */
+    RUBY_T_UNDEF:     0x16, # /**< @see ::RUBY_Qundef */:
+    RUBY_T_IMEMO:     0x1a, # /**< @see struct ::RIMemo */
+    RUBY_T_NODE:      0x1b, # /**< @see struct ::RNode */
+    RUBY_T_ICLASS:    0x1c, # /**< Hidden classes known as IClasses. */
+    RUBY_T_ZOMBIE:    0x1d, # /**< @see struct ::RZombie */
+    RUBY_T_MOVED:     0x1e, # /**< @see struct ::RMoved */
+  })
+
+  # Keep in sync with `enum ruby_value_type` in `include/ruby/internal/value_type.h`.
+  RUBY_T_MASK = 0x1f
+
+  # Keep in sync with `enum ruby_fl_type` in `include/ruby/internal/fl_type.h`.
+  RubyFlType = FlagsConverter.new({
+    RUBY_FL_PROMOTED:       (1 << 5),
+    RUBY_FL_UNUSED6:        (1 << 6),
+    RUBY_FL_FINALIZE:       (1 << 7),
+    RUBY_FL_SHAREABLE:      (1 << 8),
+    RUBY_FL_WEAK_REFERENCE: (1 << 9),
+    RUBY_FL_UNUSED10:       (1 << 10),
+    RUBY_FL_FREEZE:         (1 << 11),
+  })
+
+  # Keep in sync with `enum ruby_fl_ushift` in `include/ruby/internal/fl_type.h`.
+  RUBY_FL_USHIFT = 12
+
+  # Keep in sync with `include/ruby/internal/fl_type.h`
+  def self.FL_USER_N(n)
+    1 << (RUBY_FL_USHIFT + n)
+  end
+
+  # Keep in sync with `enum imemo_type` in `internal/imemo.h`.
+  ImemoType = EnumConverter.new({
+    imemo_env:           0,
+    imemo_cref:          1, # /*!< class reference */
+    imemo_svar:          2, # /*!< special variable */
+    imemo_throw_data:    3,
+    imemo_ifunc:         4, # /*!< iterator function */
+    imemo_memo:          5,
+    imemo_ment:          6,
+    imemo_iseq:          7,
+    imemo_tmpbuf:        8,
+    imemo_cvar_entry:    9,
+    imemo_callinfo:     10,
+    imemo_callcache:    11,
+    imemo_constcache:   12,
+    imemo_fields:       13,
+    imemo_subclasses:   14,
+    imemo_cdhash:       15,
+  })
+
+  # Keep in sync with `IMEMO_MASK` in `internal/imemo.h`.
+  IMEMO_MASK = 0x0f
+
+  # Keep in sync with both `internal/string.h` and `include/ruby/internal/core/rstring.h`.
+  StringFlags = FlagsConverter.new({
+    STR_SHARED:               FL_USER_N(0),
+    RSTRING_NOEMBED:          FL_USER_N(1),
+    STR_CHILLED_LITERAL:      FL_USER_N(2),
+    STR_CHILLED_SYMBOL_TO_S:  FL_USER_N(3),
+    RSTRING_FSTR:             FL_USER_N(17),
+  })
+
+  # Keep in sync with both `internal/array.h` and `include/ruby/internal/core/rarray.h`.
+  ArrayFlags = FlagsConverter.new({
+    RARRAY_SHARED_FLAG:       FL_USER_N(0),
+    RARRAY_EMBED_FLAG:        FL_USER_N(1),
+    RARRAY_SHARED_ROOT_FLAG:  FL_USER_N(12),
+    RARRAY_PTR_IN_USE_FLAG:   FL_USER_N(14),
+  })
+
+  RubyFlags = proc do |raw_value|
+    value = raw_value.to_i
+    builtin_type = RubyBuiltinType.convert_arg(value & RUBY_T_MASK)
+    result = {
+      raw_value: value,
+      raw_value_binary: value.to_s(2),
+      builtin_type:,
+    }
+
+    if builtin_type == :RUBY_T_IMEMO
+      result[:imemo_type] = ImemoType.convert_arg((value >> RUBY_FL_USHIFT) & IMEMO_MASK)
+    end
+
+    result[:flags] = RubyFlType.convert_arg(value)
+
+    case builtin_type
+    when :RUBY_T_STRING
+      result[:string_args] = StringFlags.convert_arg(value)
+    when :RUBY_T_ARRAY
+      result[:array_args] = ArrayFlags.convert_arg(value)
+
+      # TODO: Decode the flags for more types of interest.
+    end
+
+    result
+  end
+end

tool/timeline/lib/tracepoint.rb

@@ -0,0 +1,20 @@
+# frozen_string_literal: true
+
+module RubyTimelineTool
+  class TracePoint
+    def initialize(probe_name, where, vis_name, ph, args: nil, visualize: true)
+      @probe_name = probe_name
+      @where = where
+      @vis_name = vis_name
+      @ph = ph
+      @args = args || {}
+      @visualize = visualize
+    end
+
+    attr_reader :probe_name, :where, :vis_name, :ph, :args, :visualize
+  end
+
+  def self.tp(*args, **kwargs)
+    TracePoint.new(*args, **kwargs)
+  end
+end

tool/timeline/lib/tracepoint_defs.rb

@@ -0,0 +1,105 @@
+# frozen_string_literal: true
+
+require_relative 'tracepoint'
+require_relative 'converter_defs'
+
+module RubyTimelineTool
+  # All USDT trace points.
+  #
+  # It maps each group to an array of trace points.  The `default` group is always enabled, and
+  # other groups can be enabled using the `-g` command line option of `capture.rb`.
+  #
+  # `tp(...)` defines a trace point.  It has four compulsory arguments.
+  #
+  # 1.  The USDT probe name.  It is the `xxx` in `probe xxx()` in `probes.d`, and it is also the
+  #     `Name:` field of the output of `readelf -n`.  The `capture.rb` tool assumes the "provider
+  #     (the `Provider:` field of `readelf -n`) of the USDT is `ruby`, and we don't need to specify
+  #     it here.
+  # 2.  The place the probe is defined.  Possible values are:
+  #     -   `ruby`: It is part of the Ruby runtime, and will always be compiled into the `ruby`
+  #         executable.
+  #     -   `default`: It is part of the default GC (`default.c`).  It will be compiled into the
+  #         `ruby` executable and the default GC module if modular GC is enabled.
+  # 3.  The event name in the output timeline.
+  # 4.  The event type, as specified by the Trace Event Format.  Common types include
+  #     -   'B' and 'E': The beginning and the end of a duration event.
+  #     -   'i': An instant event.
+  #     -   'c': A counter event.
+  #
+  #     It can also have a special value 'meta' (not specified in the Trace Event Format) which
+  #     means it will not be added to the output JSON file, but will still be available for
+  #     `visualize.rb` for post-processing.
+  #
+  #     For more information about the Trace Event Format, see:
+  #     https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit?usp=sharing
+  #
+  # `tp(...)` also has some optional keyword argument.
+  #
+  # -   `args`: It is used by the `capture.rb` script to set up the arguments of the USDT probes,
+  #     and used by `visualize.rb` to convert the argument values from string (read from the log) to
+  #     JSON values.  It has the form:
+  #
+  #     ```ruby
+  #     args: {arg1: converter1, arg2: converter2, ...}
+  #     ```
+  #
+  #     The order of the key-value pairs must match the order of the arguments of the USDT trace
+  #     points (as defined in `probes.d`).
+  #
+  #     Each converter can be one of the following
+  #
+  #     -   An instance of `Converter`.
+  #     -   A symbol, such as `:to_i`, to be sent to the argument string.
+  #     -   An object that responds to `call`.
+  #
+  #     There are some converters defined in `converter_defs.rb`.
+  USDT_DEFS = {
+    'default' => [
+      # The default group visualizes the duration of each GC, each marking and each sweeping event.
+      tp('gc__mark__begin',   'default',  'gc_mark',          'B'),
+      tp('gc__mark__end',     'default',  'gc_mark',          'E'),
+      tp('gc__sweep__begin',  'default',  'gc_sweep',         'B'),
+      tp('gc__sweep__end',    'default',  'gc_sweep',         'E'),
+      tp('gc__enter',         'default',  'GCEnterExit',      'B', args: {event: GCEnterEvent}),
+      tp('gc__exit',          'default',  'GCEnterExit',      'E', args: {event: GCEnterEvent}),
+    ].freeze,
+    'mark_details' => [
+      # This group collects more detals of marking events, such as the number of objects visited.
+      tp('gc__mark_stacked_objects', 'default', 'gc_mark_stacked_objects', 'meta', args: {popped_count: :to_i}),
+    ].freeze,
+    'sweep_details' => [
+      # This group collects more detals of sweeping events, such as the number of objects swept.
+      tp('gc__sweep_page',    'default',  'gc_sweep_page',    'i', args: {slot_size: :to_i, final_slots: :to_i, freed_slots: :to_i, empty_slots: :to_i}),
+    ].freeze,
+    'obj_new' => [
+      # This group traces the creation of GC-managed objects.
+      tp('gc__obj_new',       'ruby',     'gc_obj_new',       'i', args: {obj: :to_i, flags: RubyFlags}),
+    ].freeze,
+    'obj_free' => [
+      # This group traces the invocation of `rb_gc_obj_free` which finalizes the objects when they are swept.
+      tp('gc__obj_free',      'ruby',     'gc_obj_free',      'i', args: {obj: :to_i, flags: RubyFlags}),
+    ].freeze,
+    'xmalloc' => [
+      # This group traces the invocation of `xmalloc` and `xcalloc`.
+      tp('gc__xmalloc',       'ruby',     'gc_xmalloc',       'i', args: {n: :to_i, size: :to_i}),
+      tp('gc__xcalloc',       'ruby',     'gc_xcalloc',       'i', args: {n: :to_i, size: :to_i}),
+    ].freeze,
+    'xfree' => [
+      # This group traces the invocation of `xfree`.
+      tp('gc__xfree',         'ruby',     'gc_xfree',         'i', args: {obj: :to_i, size: :to_i}),
+    ].freeze,
+    'gvl' => [
+      # This group visualizes the durations in which a thread holds the global VM lock.
+      tp('gvl__acquire',      'ruby',     'GVL',              'B'),
+      tp('gvl__release',      'ruby',     'GVL',              'E'),
+    ].freeze,
+    'rts' => [
+      # This group visualizes the event where a thread is scheduled on or off a Ractor.
+      # "RTS" stands for `ractor.thread.sched`.
+      tp('rts__set_running',  'ruby',     'rts_set_running',  'i', args: {sched: :to_i, old_thread: :to_i, new_thread: :to_i}),
+    ].freeze
+  }.freeze
+
+  # The default groups are enabled by default
+  DEFAULT_GROUPS = ['default'].freeze
+end

tool/timeline/visualize.rb

@@ -0,0 +1,246 @@
+#!/usr/bin/env ruby
+# frozen_string_literal: true
+
+require 'json'
+require 'optparse'
+require 'pathname'
+require 'zlib'
+
+require_relative 'lib/tracepoint_defs'
+require_relative 'lib/converter_defs'
+require_relative 'lib/converter'
+
+PROBE_NAME_TO_USDT = RubyTimelineTool::USDT_DEFS.values.flatten.to_h { |t| [t.probe_name, t] }
+
+module FetchStore
+  refine Hash do
+    def fetch_store(key)
+      if include?(key)
+        self[key]
+      else
+        self[key] = yield
+      end
+    end
+  end
+end
+
+using FetchStore
+
+class LogProcessor
+  def initialize(verbose: false)
+    @verbose = verbose
+    @type_id_name = {}
+    @start_time = nil
+    @results = []
+    # @current maps [pid, tid, block_name] to block.
+    @current = {}
+    @started = false
+  end
+
+  attr_accessor :started
+
+  def process_line(line)
+    if !@started
+      if line == '====RUBY_TRACING_LOG_START===='
+        @started = true
+      end
+      return
+    end
+
+    if line.include?(',')
+      process_log_line(line)
+    else
+      puts "Discarded line '#{line}'" if @verbose
+    end
+  end
+
+  def output(outfile)
+    json_str = JSON.generate(@results)
+    Zlib::GzipWriter.open(outfile) do |gz|
+      gz.write(json_str)
+    end
+  end
+
+  private
+
+  def process_log_line(line)
+    parts = line.split(',')
+    probe_name, pid, tid, ts = parts[...4]
+    pid = pid.to_i
+    tid = tid.to_i
+    ts = resolve_time(ts.to_i)
+    raw_args = parts[4...]
+
+    puts "probe_name: #{probe_name}, pid: #{pid}, tid: #{tid}, ts: #{ts}, raw_args: #{raw_args}" if @verbose
+
+    if @start_time.nil?
+      @start_time = ts
+    end
+
+    usdt_def = PROBE_NAME_TO_USDT[probe_name]
+
+    ph = usdt_def.ph
+    vis_name = usdt_def.vis_name
+
+    args = {}
+    usdt_def.args.each_pair.zip(raw_args) do |arg_def, arg_val|
+      arg_name, arg_converter = arg_def
+      begin
+        converted_val = RubyTimelineTool.convert_arg(arg_val, arg_converter)
+      rescue
+        puts "error converting argument #{arg_name}, value: [#{arg_val}]"
+        puts "line: #{line}"
+        raise
+      end
+
+      args[arg_name] = converted_val
+    end
+
+    result = { name: vis_name, ph:, pid:, tid:, ts:, args: }
+
+    if ph == 'B' || ph == 'E'
+      # Register the current block so that other events can "enrich" it.
+      set_current_block(pid, tid, result)
+    end
+
+    # Some results need special treatment.
+    case vis_name
+    when 'GCEnterExit'
+      # Register to the virtual :global TID, too.
+      set_current_block(pid, :global, result)
+    when 'gc_mark_stacked_objects'
+      enrich([pid, :global, 'GCEnterExit'], [pid, tid, 'gc_mark']) do |old_result|
+        old_result[:args].fetch_store(:gc_mark_stacked_objects) do
+          { popped_count: 0 }
+        end[:popped_count] += args[:popped_count]
+      end
+    when 'gc_sweep_page'
+      args[:free_slots] = args[:freed_slots] + args[:empty_slots]
+      enrich([pid, :global, 'GCEnterExit'], [pid, tid, 'gc_sweep']) do |old_result|
+        old_dict = old_result[:args].fetch_store(:gc_sweep_page) do
+          { swept_pages: 0, final_slots: 0, freed_slots: 0, empty_slots: 0, free_slots: 0 }
+        end
+        old_dict[:swept_pages] += 1
+        old_dict[:final_slots] += args[:final_slots]
+        old_dict[:freed_slots] += args[:freed_slots]
+        old_dict[:empty_slots] += args[:empty_slots]
+        old_dict[:free_slots] += args[:free_slots]
+      end
+    when 'rts_set_running'
+      sched = args[:sched]
+      sched_hex = "0x#{sched.to_s(16)}"
+      # A virtual TID for the rb_thread_sched instance.
+      sched_id = "sched-#{sched_hex}"
+      prev = get_current(pid, sched_id, 'RTS')
+      if !prev.nil?
+        block_end = result.dup.update({
+          name: 'RTS',
+          ph: 'E',
+          tid: sched_id,
+          args: {}
+        })
+        @results << block_end
+        clear_current(pid, sched_id, 'RTS')
+      end
+
+      if args[:new_thread] != 0
+        block_begin = result.dup.update({
+          name: 'RTS',
+          ph: 'B',
+          tid: sched_id,
+          args: {
+            sched:,
+            sched_hex:,
+            thread: args[:new_thread],
+          }
+        })
+        @results << block_begin
+        set_current(pid, sched_id, 'RTS', block_begin)
+      end
+    end
+
+    if result[:ph] != 'meta'
+      @results << result
+    end
+  end
+
+  def resolve_time(ts)
+    if @start_time.nil?
+      @start_time = ts
+    end
+    (ts - @start_time) / 1000.0
+  end
+
+  def set_current(pid, tid, key, value)
+    @current[[pid, tid, key]] = value
+  end
+
+  def get_current(pid, tid, key)
+    @current[[pid, tid, key]]
+  end
+
+  def clear_current(pid, tid, key)
+    @current.delete([pid, tid, key])
+  end
+
+  def set_current_block(pid, tid, result)
+    case result[:ph]
+    when 'B'
+      set_current(pid, tid, result[:name], result)
+    when 'E'
+      clear_current(pid, tid, result[:name])
+    else
+      raise "unexpected ph: #{result}"
+    end
+  end
+
+  # Look up an entry in the `@current` hash so that
+  # you can add more arguments or make adjustments to it.
+  def enrich(*targets)
+    targets.each do |target|
+      case target
+      in [pid, tid, key]
+        result = get_current(pid, tid, key)
+        if !result.nil?
+          yield result
+        end
+      end
+    end
+  end
+end
+
+def main
+  options = {}
+
+  OptionParser.new do |parser|
+    parser.on('-v', '--verbose', TrueClass, 'Print verbose messages.  For debugging.')
+    parser.on('-d', '--dry-run', TrueClass, 'Dry run. DO not actually write into output file.')
+  end.parse!(into: options)
+
+  input = ARGV[0]
+  if input.nil?
+    raise 'Need positional argument'
+  end
+
+  input_path = Pathname.new(input)
+  if !input_path.file?
+    raise "File #{input_path} does not exist"
+  end
+
+  output_path = input_path.dirname / "#{input_path.basename}.json.gz"
+
+  log_processor = LogProcessor.new(verbose: options[:verbose])
+
+  input_path.each_line(chomp: true) do |line|
+    log_processor.process_line(line)
+  end
+
+  if options[:'dry-run']
+    puts "Dry run.  Output file: #{output_path}"
+  else
+    puts "Writing to output file: #{output_path}"
+    log_processor.output(output_path)
+  end
+end
+
+main

vm_sync.c

@@ -4,6 +4,7 @@
 #include "vm_sync.h"
 #include "ractor_core.h"
 #include "vm_debug.h"
+#include "probes.h"
 
 void rb_ractor_sched_barrier_start(rb_vm_t *vm, rb_ractor_t *cr);
 void rb_ractor_sched_barrier_join(rb_vm_t *vm, rb_ractor_t *cr);
@@ -115,6 +116,10 @@ vm_lock_enter(rb_ractor_t *cr, rb_vm_t *vm, bool locked, bool no_barrier, unsign
 
     RUBY_DEBUG_LOG2(file, line, "rec:%u owner:%u", vm->ractor.sync.lock_rec,
                     (unsigned int)rb_ractor_id(vm->ractor.sync.lock_owner));
+
+    if (RUBY_DTRACE_GVL_ACQUIRE_ENABLED()) {
+        RUBY_DTRACE_GVL_ACQUIRE();
+    }
 }
 
 static void
@@ -139,6 +144,10 @@ vm_lock_leave(rb_vm_t *vm, bool no_barrier, unsigned int *lev APPEND_LOCATION_AR
     }
 #endif
 
+    if (RUBY_DTRACE_GVL_RELEASE_ENABLED()) {
+        RUBY_DTRACE_GVL_RELEASE();
+    }
+
     vm->ractor.sync.lock_rec--;
     *lev = vm->ractor.sync.lock_rec;