From b55d66c6ee918c2c5de0530e3945d0d56c4a2cd6 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Mon, 27 May 2024 14:05:25 +0200
Subject: [PATCH 01/18] Add Crystal::System::Thread.current_thread? +
 Thread#scheduler?

The internal runtime may need to access the current thread and scheduler
before they're actually defined *and* without defining them (e.g. tracing).
---
 src/crystal/system/thread.cr       | 12 ++++++++++++
 src/crystal/system/unix/pthread.cr | 10 ++++++++++
 src/crystal/system/win32/thread.cr |  4 ++++
 3 files changed, 26 insertions(+)

diff --git a/src/crystal/system/thread.cr b/src/crystal/system/thread.cr
index d6a6e5653276..03b00f2779f4 100644
--- a/src/crystal/system/thread.cr
+++ b/src/crystal/system/thread.cr
@@ -10,6 +10,8 @@ module Crystal::System::Thread
 
   # def self.current_thread : ::Thread
 
+  # def self.current_thread? : ::Thread?
+
   # def self.current_thread=(thread : ::Thread)
 
   # private def system_join : Exception?
@@ -102,6 +104,11 @@ class Thread
     Crystal::System::Thread.current_thread
   end
 
+  # :nodoc:
+  def self.current? : Thread?
+    Crystal::System::Thread.current_thread?
+  end
+
   # Associates the Thread object to the running system thread.
   protected def self.current=(current : Thread) : Thread
     Crystal::System::Thread.current_thread = current
@@ -122,6 +129,11 @@ class Thread
   # :nodoc:
   getter scheduler : Crystal::Scheduler { Crystal::Scheduler.new(self) }
 
+  # :nodoc:
+  def scheduler? : ::Crystal::Scheduler?
+    @scheduler
+  end
+
   protected def start
     Thread.threads.push(self)
     Thread.current = self
diff --git a/src/crystal/system/unix/pthread.cr b/src/crystal/system/unix/pthread.cr
index f96d0bbf75ba..4b357b04281c 100644
--- a/src/crystal/system/unix/pthread.cr
+++ b/src/crystal/system/unix/pthread.cr
@@ -55,6 +55,12 @@ module Crystal::System::Thread
       end
     end
 
+    def self.current_thread? : ::Thread?
+      if ptr = LibC.pthread_getspecific(@@current_key)
+        ptr.as(::Thread)
+      end
+    end
+
     def self.current_thread=(thread : ::Thread)
       ret = LibC.pthread_setspecific(@@current_key, thread.as(Void*))
       raise RuntimeError.from_os_error("pthread_setspecific", Errno.new(ret)) unless ret == 0
@@ -63,6 +69,10 @@ module Crystal::System::Thread
   {% else %}
     @[ThreadLocal]
     class_property current_thread : ::Thread { ::Thread.new }
+
+    def self.current_thread? : ::Thread?
+      @@current_thread
+    end
   {% end %}
 
   private def system_join : Exception?
diff --git a/src/crystal/system/win32/thread.cr b/src/crystal/system/win32/thread.cr
index 2b44f66c28ce..9507e332b422 100644
--- a/src/crystal/system/win32/thread.cr
+++ b/src/crystal/system/win32/thread.cr
@@ -47,6 +47,10 @@ module Crystal::System::Thread
   @[ThreadLocal]
   class_property current_thread : ::Thread { ::Thread.new }
 
+  def self.current_thread? : ::Thread?
+    @@current_thread
+  end
+
   private def system_join : Exception?
     if LibC.WaitForSingleObject(@system_handle, LibC::INFINITE) != LibC::WAIT_OBJECT_0
       return RuntimeError.from_winerror("WaitForSingleObject")

From 824e2af74697bfc1c6f0f4c3aeefa97649f8dff2 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Mon, 27 May 2024 14:07:54 +0200
Subject: [PATCH 02/18] Initial Crystal.trace implementation

---
 src/concurrent.cr        |   2 +
 src/crystal/main.cr      |   1 +
 src/crystal/scheduler.cr |  39 +++++----
 src/crystal/tracing.cr   | 173 +++++++++++++++++++++++++++++++++++++++
 src/gc/boehm.cr          |  99 ++++++++++++++++++++--
 src/gc/none.cr           |   5 ++
 6 files changed, 299 insertions(+), 20 deletions(-)
 create mode 100644 src/crystal/tracing.cr

diff --git a/src/concurrent.cr b/src/concurrent.cr
index af2f0aecf736..9df66306bb1d 100644
--- a/src/concurrent.cr
+++ b/src/concurrent.cr
@@ -1,6 +1,7 @@
 require "fiber"
 require "channel"
 require "crystal/scheduler"
+require "crystal/tracing"
 
 # Blocks the current fiber for the specified number of seconds.
 #
@@ -59,6 +60,7 @@ end
 # ```
 def spawn(*, name : String? = nil, same_thread = false, &block)
   fiber = Fiber.new(name, &block)
+  Crystal.trace :sched, :spawn, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?"
   {% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %}
   fiber.enqueue
   fiber
diff --git a/src/crystal/main.cr b/src/crystal/main.cr
index 059a822c5ff4..625238229c58 100644
--- a/src/crystal/main.cr
+++ b/src/crystal/main.cr
@@ -34,6 +34,7 @@ module Crystal
   # same can be accomplished with `at_exit`. But in some cases
   # redefinition of C's main is needed.
   def self.main(&block)
+    {% if flag?(:tracing) %} Crystal::Tracing.init {% end %}
     GC.init
 
     status =
diff --git a/src/crystal/scheduler.cr b/src/crystal/scheduler.cr
index 4796226ce8e9..6d39cc2bc6eb 100644
--- a/src/crystal/scheduler.cr
+++ b/src/crystal/scheduler.cr
@@ -25,21 +25,23 @@ class Crystal::Scheduler
   end
 
   def self.enqueue(fiber : Fiber) : Nil
-    thread = Thread.current
-    scheduler = thread.scheduler
+    Crystal.trace :sched, :enqueue, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" do
+      thread = Thread.current
+      scheduler = thread.scheduler
 
-    {% if flag?(:preview_mt) %}
-      th = fiber.get_current_thread
-      th ||= fiber.set_current_thread(scheduler.find_target_thread)
+      {% if flag?(:preview_mt) %}
+        th = fiber.get_current_thread
+        th ||= fiber.set_current_thread(scheduler.find_target_thread)
 
-      if th == thread
+        if th == thread
+          scheduler.enqueue(fiber)
+        else
+          th.scheduler.send_fiber(fiber)
+        end
+      {% else %}
         scheduler.enqueue(fiber)
-      else
-        th.scheduler.send_fiber(fiber)
-      end
-    {% else %}
-      scheduler.enqueue(fiber)
-    {% end %}
+      {% end %}
+    end
   end
 
   def self.enqueue(fibers : Enumerable(Fiber)) : Nil
@@ -49,6 +51,7 @@ class Crystal::Scheduler
   end
 
   def self.reschedule : Nil
+    Crystal.trace :sched, :reschedule
     Thread.current.scheduler.reschedule
   end
 
@@ -58,10 +61,13 @@ class Crystal::Scheduler
   end
 
   def self.sleep(time : Time::Span) : Nil
+    Crystal.trace :sched, :sleep, "duration=%lld", time.total_nanoseconds.to_i64!
     Thread.current.scheduler.sleep(time)
   end
 
   def self.yield : Nil
+    Crystal.trace :sched, :yield
+
     # TODO: Fiber switching and libevent for wasm32
     {% unless flag?(:wasm32) %}
       Thread.current.scheduler.sleep(0.seconds)
@@ -109,6 +115,7 @@ class Crystal::Scheduler
   end
 
   protected def resume(fiber : Fiber) : Nil
+    Crystal.trace :sched, :resume, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?"
     validate_resumable(fiber)
 
     {% if flag?(:preview_mt) %}
@@ -149,7 +156,9 @@ class Crystal::Scheduler
         resume(runnable) unless runnable == @thread.current_fiber
         break
       else
-        @event_loop.run(blocking: true)
+        Crystal.trace :sched, "event_loop" do
+          @event_loop.run(blocking: true)
+        end
       end
     end
   end
@@ -190,7 +199,9 @@ class Crystal::Scheduler
         else
           @sleeping = true
           @lock.unlock
-          fiber = fiber_channel.receive
+
+          Crystal.trace :sched, "mt:sleeping"
+          fiber = Crystal.trace(:sched, "mt:slept") { fiber_channel.receive }
 
           @lock.lock
           @sleeping = false
diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
new file mode 100644
index 000000000000..5c5301f55e84
--- /dev/null
+++ b/src/crystal/tracing.cr
@@ -0,0 +1,173 @@
+module Crystal
+  {% if flag?(:tracing) %}
+    # :nodoc:
+    module Tracing
+      # IO-like object with a fixed capacity but dynamic size within the
+      # buffer's capacity (i.e. `0 <= size <= N`). Stops writing to the internal
+      # buffer when capacity is reached; further writes are skipped.
+      struct BufferIO(N)
+        getter size : Int32
+
+        def initialize
+          @buf = uninitialized UInt8[N]
+          @size = 0
+        end
+
+        def write(bytes : Bytes) : Nil
+          pos = @size
+          remaining = N - pos
+          return if remaining == 0
+
+          n = bytes.size.clamp(..remaining)
+          bytes.to_unsafe.copy_to(@buf.to_unsafe + pos, n)
+          @size = pos + n
+        end
+
+        def to_slice : Bytes
+          Bytes.new(@buf.to_unsafe, @size)
+        end
+      end
+
+      @[Flags]
+      enum Section
+        Gc
+        Sched
+      end
+
+      @@sections = Section::None
+      @@startup_tick = 0_u64
+
+      @[AlwaysInline]
+      def self.enabled?(section : Section) : Bool
+        @@sections.includes?(section)
+      end
+
+      @[AlwaysInline]
+      def self.startup_tick : UInt64
+        @@startup_tick
+      end
+
+      # Setups tracing, parsing the `CRYSTAL_TRACE` environment variable to
+      # enable the sections to trace (`gc` and/or `sched`).
+      #
+      # This should be the first thing called in main, maybe even before the GC
+      # itself is initialized. The function assumes neither the GC nor ENV nor
+      # anything is available and musn't allocate into the GC HEAP.
+      def self.init
+        @@sections = Section::None
+        @@startup_tick = ::Crystal::System::Time.ticks
+
+        {% if flag?(:win32) %}
+          buf = uninitialized UInt16[256]
+          name = UInt16.static_array({% for chr in "CRYSTAL_TRACE".chars %}{{chr.ord}}, {% end %} 0)
+          len = LibC.GetEnvironmentVariableW(name, buf, buf.size)
+          debug = buf.to_slice[0...len] if len > 0
+        {% else %}
+          if ptr = LibC.getenv("CRYSTAL_TRACE")
+            len = LibC.strlen(ptr)
+            debug = Slice.new(ptr, len) if len > 0
+          end
+        {% end %}
+
+        return unless debug
+
+        each_token(debug) do |token|
+          \{% begin %}
+            case token
+            \{% for name in Section.constants %}
+              when \{{name.downcase.id.stringify}}.to_slice
+                @@sections |= Section::\{{name.id}}
+            \{% end %}
+            end
+          \{% end %}
+        end
+      end
+
+      private def self.each_token(bytes, delim = ',', &)
+        while e = bytes.index(delim.ord)
+          yield bytes[0, e]
+          bytes = bytes[(e + 1)..]
+        end
+        yield bytes[0..] unless bytes.size == 0
+      end
+
+      # Formats and prints a log message to stderr. The generated message is
+      # limited to 512 bytes (PIPE_BUF) after which it will be truncated. Being
+      # below PIPE_BUF the message shall be written atomically to stderr,
+      # avoiding interleaved or smashed traces from multiple threads.
+      #
+      # Windows may not have the same guarantees but the buffering should limit
+      # these from happening.
+      def self.log(fmt : String, *args) : Nil
+        buf = BufferIO(512).new
+        Crystal::System.printf(fmt, *args) { |bytes| buf.write bytes }
+        Crystal::System.print_error(buf.to_slice)
+      end
+    end
+
+    macro trace(section, operation, fmt = "", *args, &block)
+      if ::Crystal::Tracing.enabled?(\{{section}})
+        %tick = ::Crystal::System::Time.ticks
+        %time = %tick - ::Crystal::Tracing.startup_tick
+        \{% if block %}
+          %ret = \{{yield}}
+          %duration = ::Crystal::System::Time.ticks - %tick
+          ::Crystal.trace_end(%time, %duration, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}})
+          %ret
+        \{% else %}
+          ::Crystal.trace_end(%time, nil, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}})
+          nil
+        \{% end %}
+      else
+        \{{yield}}
+      end
+    end
+
+    # :nodoc:
+    macro trace_end(time, duration, section, operation, fmt = "", *args)
+      {% if flag?(:wasm32) %}
+        # WASM doesn't have threads (and fibers aren't implemented either)
+        ::Crystal::Tracing.log("\{{section.id}}.\{{operation.id}} %lld duration=%lld \{{fmt.id}}\n",
+                               \{{time}}, \{{duration}}, \{{args.splat}})
+      {% else %}
+        {% thread_type = flag?(:linux) ? "0x%lx".id : "%p".id %}
+
+        # we may start to trace *before* Thread.current and other objects have
+        # been allocated, they're lazily allocated and since we trace GC.malloc we
+        # must skip the objects until they're allocated (otherwise we hit infinite
+        # recursion): malloc -> trace -> malloc -> trace -> ...
+        if (%thread = Thread.current?) && (%fiber = %thread.current_fiber?)
+          ::Crystal::Tracing.log(
+            "\{{section.id}}.\{{operation.id}} %lld thread={{thread_type}}:%s fiber=%p:%s duration=%lld \{{fmt.id}}\n",
+            \{{time}}, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{duration}}, \{{args.splat}})
+        else
+          %thread_handle = %thread ? %thread.@system_handle : Crystal::System::Thread.current_handle
+          ::Crystal::Tracing.log(
+            "\{{section.id}}.\{{operation.id}} %lld thread={{thread_type}}:%s duration=%lld \{{fmt.id}}\n",
+            \{{time}}, %thread_handle, %thread.try(&.name) || "?", \{{duration}}, \{{args.splat}})
+        end
+      {% end %}
+    end
+  {% else %}
+    # :nodoc:
+    module Tracing
+      def self.init
+      end
+
+      def self.enabled?(section)
+        false
+      end
+
+      def self.log(fmt : String, *args)
+      end
+    end
+
+    macro trace(section, operation, fmt = "", *args, &block)
+      \{{yield}}
+    end
+
+    # :nodoc:
+    macro trace_end(time, duration, section, operation, fmt = "", *args)
+    end
+  {% end %}
+end
diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr
index 29ae825adab1..7a0fee3b12a9 100644
--- a/src/gc/boehm.cr
+++ b/src/gc/boehm.cr
@@ -1,6 +1,7 @@
 {% if flag?(:preview_mt) %}
   require "crystal/rw_lock"
 {% end %}
+require "crystal/tracing"
 
 # MUSL: On musl systems, libpthread is empty. The entire library is already included in libc.
 # The empty library is only available for POSIX compatibility. We don't need to link it.
@@ -113,7 +114,32 @@ lib LibGC
     $stackbottom = GC_stackbottom : Void*
   {% end %}
 
-  fun set_on_collection_event = GC_set_on_collection_event(cb : ->)
+  alias OnHeapResizeProc = Word ->
+  fun set_on_heap_resize = GC_set_on_heap_resize(OnHeapResizeProc)
+  fun get_on_heap_resize = GC_get_on_heap_resize : OnHeapResizeProc
+
+  enum EventType
+    START # COLLECTION
+    MARK_START
+    MARK_END
+    RECLAIM_START
+    RECLAIM_END
+    END              # COLLECTION
+    PRE_STOP_WORLD   # STOPWORLD_BEGIN
+    POST_STOP_WORLD  # STOPWORLD_END
+    PRE_START_WORLD  # STARTWORLD_BEGIN
+    POST_START_WORLD # STARTWORLD_END
+    THREAD_SUSPENDED
+    THREAD_UNSUSPENDED
+  end
+
+  alias OnCollectionEventProc = EventType ->
+  fun set_on_collection_event = GC_set_on_collection_event(cb : OnCollectionEventProc)
+  fun get_on_collection_event = GC_get_on_collection_event : OnCollectionEventProc
+
+  alias OnThreadEventProc = EventType, Void* ->
+  fun set_on_thread_event = GC_set_on_thread_event(cb : OnThreadEventProc)
+  fun get_on_thread_event = GC_get_on_thread_event : OnThreadEventProc
 
   $gc_no = GC_gc_no : Word
   $bytes_found = GC_bytes_found : SignedWord
@@ -144,17 +170,23 @@ module GC
 
   # :nodoc:
   def self.malloc(size : LibC::SizeT) : Void*
-    LibGC.malloc(size)
+    Crystal.trace :gc, :malloc, "size=%lu", size do
+      LibGC.malloc(size)
+    end
   end
 
   # :nodoc:
   def self.malloc_atomic(size : LibC::SizeT) : Void*
-    LibGC.malloc_atomic(size)
+    Crystal.trace :gc, :malloc, "size=%lu atomic=1", size do
+      LibGC.malloc_atomic(size)
+    end
   end
 
   # :nodoc:
   def self.realloc(ptr : Void*, size : LibC::SizeT) : Void*
-    LibGC.realloc(ptr, size)
+    Crystal.trace :gc, :realloc, "size=%lu", size do
+      LibGC.realloc(ptr, size)
+    end
   end
 
   def self.init : Nil
@@ -166,6 +198,14 @@ module GC
     LibGC.set_start_callback ->do
       GC.lock_write
     end
+
+    {% if flag?(:tracing) %}
+      if ::Crystal::Tracing.enabled?(:gc)
+        set_on_heap_resize_proc
+        set_on_collection_events_proc
+      end
+    {% end %}
+
     # By default the GC warns on big allocations/reallocations. This
     # is of limited use and pollutes program output with warnings.
     LibGC.set_warn_proc ->(msg, v) do
@@ -178,8 +218,53 @@ module GC
     end
   end
 
+  {% if flag?(:tracing) %}
+    @@on_heap_resize : LibGC::OnHeapResizeProc?
+    @@on_collection_event : LibGC::OnCollectionEventProc?
+
+    @@collect_start = uninitialized Time::Span
+    @@mark_start = uninitialized Time::Span
+    @@sweep_start = uninitialized Time::Span
+
+    private def self.set_on_heap_resize_proc : Nil
+      @@on_heap_resize = LibGC.get_on_heap_resize
+
+      LibGC.set_on_heap_resize(->(new_size : LibGC::Word) {
+        Crystal.trace :gc, :heap_resize, "size=%llu", UInt64.new(new_size)
+        @@on_heap_resize.try(&.call(new_size))
+      })
+    end
+
+    private def self.set_on_collection_events_proc : Nil
+      @@on_collection_event = LibGC.get_on_collection_event
+
+      LibGC.set_on_collection_event(->(event_type : LibGC::EventType) {
+        case event_type
+        when .start?
+          @@collect_start = Time.monotonic
+        when .mark_start?
+          @@mark_start = Time.monotonic
+        when .reclaim_start?
+          @@sweep_start = Time.monotonic
+        when .end?
+          duration = ::Time.monotonic - @@collect_start
+          Crystal.trace_end @@collect_start, duration, "gc", "collect"
+        when .mark_end?
+          duration = ::Time.monotonic - @@mark_start
+          Crystal.trace_end @@collect_start, duration, "gc", "collect:mark"
+        when .reclaim_end?
+          duration = ::Time.monotonic - @@sweep_start
+          Crystal.trace_end @@collect_start, duration, "gc", "collect:sweep"
+        end
+        @@on_collection_event.try(&.call(event_type))
+      })
+    end
+  {% end %}
+
   def self.collect
-    LibGC.collect
+    Crystal.trace :gc, :collect do
+      LibGC.collect
+    end
   end
 
   def self.enable
@@ -195,7 +280,9 @@ module GC
   end
 
   def self.free(pointer : Void*) : Nil
-    LibGC.free(pointer)
+    Crystal.trace :gc, :free do
+      LibGC.free(pointer)
+    end
   end
 
   def self.add_finalizer(object : Reference) : Nil
diff --git a/src/gc/none.cr b/src/gc/none.cr
index c71ab05ccd8d..92585a769cc8 100644
--- a/src/gc/none.cr
+++ b/src/gc/none.cr
@@ -1,6 +1,7 @@
 {% if flag?(:win32) %}
   require "c/process"
 {% end %}
+require "crystal/tracing"
 
 module GC
   def self.init
@@ -8,16 +9,19 @@ module GC
 
   # :nodoc:
   def self.malloc(size : LibC::SizeT) : Void*
+    Crystal.trace :gc, :malloc, "size=%lu", size
     LibC.malloc(size)
   end
 
   # :nodoc:
   def self.malloc_atomic(size : LibC::SizeT) : Void*
+    Crystal.trace :gc, :malloc, "size=%lu atomic=1", size
     LibC.malloc(size)
   end
 
   # :nodoc:
   def self.realloc(pointer : Void*, size : LibC::SizeT) : Void*
+    Crystal.trace :gc, :realloc, "size=%lu", size
     LibC.realloc(pointer, size)
   end
 
@@ -31,6 +35,7 @@ module GC
   end
 
   def self.free(pointer : Void*) : Nil
+    Crystal.trace :gc, :free
     LibC.free(pointer)
   end
 

From eddc00537c8d887711a3e31a89131abe1f8cbab7 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Mon, 27 May 2024 17:01:17 +0200
Subject: [PATCH 03/18] Line protocol with abstract metadata (named tuple)

---
 src/concurrent.cr                 |   2 +-
 src/crystal/scheduler.cr          |   6 +-
 src/crystal/system/print_error.cr |   2 +-
 src/crystal/tracing.cr            | 124 +++++++++++++++++++-----------
 src/gc/boehm.cr                   |  32 ++++----
 src/gc/none.cr                    |   6 +-
 6 files changed, 101 insertions(+), 71 deletions(-)

diff --git a/src/concurrent.cr b/src/concurrent.cr
index 9df66306bb1d..b9eee6ea7aa2 100644
--- a/src/concurrent.cr
+++ b/src/concurrent.cr
@@ -60,7 +60,7 @@ end
 # ```
 def spawn(*, name : String? = nil, same_thread = false, &block)
   fiber = Fiber.new(name, &block)
-  Crystal.trace :sched, :spawn, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?"
+  Crystal.trace :sched, :spawn, fiber: fiber
   {% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %}
   fiber.enqueue
   fiber
diff --git a/src/crystal/scheduler.cr b/src/crystal/scheduler.cr
index 6d39cc2bc6eb..193197bdb712 100644
--- a/src/crystal/scheduler.cr
+++ b/src/crystal/scheduler.cr
@@ -25,7 +25,7 @@ class Crystal::Scheduler
   end
 
   def self.enqueue(fiber : Fiber) : Nil
-    Crystal.trace :sched, :enqueue, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" do
+    Crystal.trace :sched, :enqueue, fiber: fiber do
       thread = Thread.current
       scheduler = thread.scheduler
 
@@ -61,7 +61,7 @@ class Crystal::Scheduler
   end
 
   def self.sleep(time : Time::Span) : Nil
-    Crystal.trace :sched, :sleep, "duration=%lld", time.total_nanoseconds.to_i64!
+    Crystal.trace :sched, :sleep, for: time.total_nanoseconds.to_i64!
     Thread.current.scheduler.sleep(time)
   end
 
@@ -115,7 +115,7 @@ class Crystal::Scheduler
   end
 
   protected def resume(fiber : Fiber) : Nil
-    Crystal.trace :sched, :resume, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?"
+    Crystal.trace :sched, :resume, fiber: fiber
     validate_resumable(fiber)
 
     {% if flag?(:preview_mt) %}
diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr
index f58bef1c4ff6..ec17f325a725 100644
--- a/src/crystal/system/print_error.cr
+++ b/src/crystal/system/print_error.cr
@@ -109,7 +109,7 @@ module Crystal::System
   end
 
   # simplified version of `Int#internal_to_s`
-  private def self.to_int_slice(num, base, signed, width, &)
+  protected def self.to_int_slice(num, base, signed, width, &)
     if num == 0
       yield "0".to_slice
       return
diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index 5c5301f55e84..3c50b4395ee1 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -23,6 +23,29 @@ module Crystal
           @size = pos + n
         end
 
+        def write(string : String) : Nil
+          write string.to_slice
+        end
+
+        def write(fiber : Fiber) : Nil
+          write fiber.as(Void*)
+          write ":"
+          write fiber.name || "?"
+        end
+
+        def write(ptr : Pointer) : Nil
+          write "0x"
+          Crystal::System.to_int_slice(ptr.address, 16, true, 2) { |bytes| write(bytes) }
+        end
+
+        def write(int : Int::Signed) : Nil
+          Crystal::System.to_int_slice(int, 10, true, 2) { |bytes| write(bytes) }
+        end
+
+        def write(uint : Int::Unsigned) : Nil
+          Crystal::System.to_int_slice(uint, 10, false, 2) { |bytes| write(bytes) }
+        end
+
         def to_slice : Bytes
           Bytes.new(@buf.to_unsafe, @size)
         end
@@ -91,63 +114,74 @@ module Crystal
         yield bytes[0..] unless bytes.size == 0
       end
 
-      # Formats and prints a log message to stderr. The generated message is
-      # limited to 512 bytes (PIPE_BUF) after which it will be truncated. Being
-      # below PIPE_BUF the message shall be written atomically to stderr,
-      # avoiding interleaved or smashed traces from multiple threads.
-      #
-      # Windows may not have the same guarantees but the buffering should limit
-      # these from happening.
-      def self.log(fmt : String, *args) : Nil
+      # :nodoc:
+      def self.log(section : String, operation : String, time : UInt64, **metadata)
         buf = BufferIO(512).new
-        Crystal::System.printf(fmt, *args) { |bytes| buf.write bytes }
-        Crystal::System.print_error(buf.to_slice)
+        buf.write section
+        buf.write "."
+        buf.write operation
+        buf.write " "
+        buf.write time
+
+        {% unless flag?(:wasm32) %}
+          # WASM doesn't have threads (and fibers aren't implemented either)
+          #
+          # We also start to trace *before* Thread.current and other objects have
+          # been allocated, they're lazily allocated and since we trace GC.malloc we
+          # must skip the objects until they're allocated (otherwise we hit infinite
+          # recursion): malloc -> trace -> malloc -> trace -> ...
+          thread = ::Thread.current?
+
+          buf.write " thread="
+          {% if flag?(:linux) %}
+            buf.write Pointer(Void).new(thread ? thread.@system_handle : System::Thread.current_handle)
+          {% else %}
+            buf.write thread ? thread.@system_handle : System::Thread.current_handle
+          {% end %}
+          buf.write ":"
+          buf.write thread.try(&.name) || "?"
+
+          if thread && (fiber = thread.current_fiber?)
+            buf.write " fiber="
+            buf.write fiber
+          end
+        {% end %}
+
+        metadata.each do |key, value|
+          buf.write " "
+          buf.write key.to_s
+          buf.write "="
+          buf.write value
+        end
+
+        buf.write "\n"
+        System.print_error(buf.to_slice)
       end
     end
 
-    macro trace(section, operation, fmt = "", *args, &block)
+    # Formats and prints a log message to stderr. The generated message is
+    # limited to 512 bytes (PIPE_BUF) after which it will be truncated. Being
+    # below PIPE_BUF the message shall be written atomically to stderr,
+    # avoiding interleaved or smashed traces from multiple threads.
+    #
+    # Windows may not have the same guarantees but the buffering should limit
+    # these from happening.
+    macro trace(section, operation, tick = nil, **metadata, &block)
       if ::Crystal::Tracing.enabled?(\{{section}})
-        %tick = ::Crystal::System::Time.ticks
-        %time = %tick - ::Crystal::Tracing.startup_tick
+        %tick = \{{tick}} || ::Crystal::System::Time.ticks
         \{% if block %}
           %ret = \{{yield}}
           %duration = ::Crystal::System::Time.ticks - %tick
-          ::Crystal.trace_end(%time, %duration, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}})
+          ::Crystal::Tracing.log(\{{section.id.stringify}}, \{{operation.id.stringify}}, %tick, duration: %duration, \{{metadata.double_splat}})
           %ret
         \{% else %}
-          ::Crystal.trace_end(%time, nil, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}})
+          ::Crystal::Tracing.log(\{{section.id.stringify}}, \{{operation.id.stringify}}, %tick, \{{metadata.double_splat}})
           nil
         \{% end %}
       else
         \{{yield}}
       end
     end
-
-    # :nodoc:
-    macro trace_end(time, duration, section, operation, fmt = "", *args)
-      {% if flag?(:wasm32) %}
-        # WASM doesn't have threads (and fibers aren't implemented either)
-        ::Crystal::Tracing.log("\{{section.id}}.\{{operation.id}} %lld duration=%lld \{{fmt.id}}\n",
-                               \{{time}}, \{{duration}}, \{{args.splat}})
-      {% else %}
-        {% thread_type = flag?(:linux) ? "0x%lx".id : "%p".id %}
-
-        # we may start to trace *before* Thread.current and other objects have
-        # been allocated, they're lazily allocated and since we trace GC.malloc we
-        # must skip the objects until they're allocated (otherwise we hit infinite
-        # recursion): malloc -> trace -> malloc -> trace -> ...
-        if (%thread = Thread.current?) && (%fiber = %thread.current_fiber?)
-          ::Crystal::Tracing.log(
-            "\{{section.id}}.\{{operation.id}} %lld thread={{thread_type}}:%s fiber=%p:%s duration=%lld \{{fmt.id}}\n",
-            \{{time}}, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{duration}}, \{{args.splat}})
-        else
-          %thread_handle = %thread ? %thread.@system_handle : Crystal::System::Thread.current_handle
-          ::Crystal::Tracing.log(
-            "\{{section.id}}.\{{operation.id}} %lld thread={{thread_type}}:%s duration=%lld \{{fmt.id}}\n",
-            \{{time}}, %thread_handle, %thread.try(&.name) || "?", \{{duration}}, \{{args.splat}})
-        end
-      {% end %}
-    end
   {% else %}
     # :nodoc:
     module Tracing
@@ -158,16 +192,12 @@ module Crystal
         false
       end
 
-      def self.log(fmt : String, *args)
+      def self.log(section : String, operation : String, time : UInt64, **metadata)
       end
     end
 
-    macro trace(section, operation, fmt = "", *args, &block)
+    macro trace(section, operation, **metadata, &block)
       \{{yield}}
     end
-
-    # :nodoc:
-    macro trace_end(time, duration, section, operation, fmt = "", *args)
-    end
   {% end %}
 end
diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr
index 7a0fee3b12a9..9b9b1ce141ef 100644
--- a/src/gc/boehm.cr
+++ b/src/gc/boehm.cr
@@ -170,21 +170,21 @@ module GC
 
   # :nodoc:
   def self.malloc(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, "size=%lu", size do
+    Crystal.trace :gc, :malloc, size: size do
       LibGC.malloc(size)
     end
   end
 
   # :nodoc:
   def self.malloc_atomic(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, "size=%lu atomic=1", size do
+    Crystal.trace :gc, :malloc, size: size, atomic: 1 do
       LibGC.malloc_atomic(size)
     end
   end
 
   # :nodoc:
   def self.realloc(ptr : Void*, size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :realloc, "size=%lu", size do
+    Crystal.trace :gc, :realloc, size: size do
       LibGC.realloc(ptr, size)
     end
   end
@@ -222,15 +222,15 @@ module GC
     @@on_heap_resize : LibGC::OnHeapResizeProc?
     @@on_collection_event : LibGC::OnCollectionEventProc?
 
-    @@collect_start = uninitialized Time::Span
-    @@mark_start = uninitialized Time::Span
-    @@sweep_start = uninitialized Time::Span
+    @@collect_start = 0_u64
+    @@mark_start = 0_u64
+    @@sweep_start = 0_u64
 
     private def self.set_on_heap_resize_proc : Nil
       @@on_heap_resize = LibGC.get_on_heap_resize
 
       LibGC.set_on_heap_resize(->(new_size : LibGC::Word) {
-        Crystal.trace :gc, :heap_resize, "size=%llu", UInt64.new(new_size)
+        Crystal.trace :gc, :heap_resize, size: new_size
         @@on_heap_resize.try(&.call(new_size))
       })
     end
@@ -241,20 +241,20 @@ module GC
       LibGC.set_on_collection_event(->(event_type : LibGC::EventType) {
         case event_type
         when .start?
-          @@collect_start = Time.monotonic
+          @@collect_start = Crystal::System::Time.ticks
         when .mark_start?
-          @@mark_start = Time.monotonic
+          @@mark_start = Crystal::System::Time.ticks
         when .reclaim_start?
-          @@sweep_start = Time.monotonic
+          @@sweep_start = Crystal::System::Time.ticks
         when .end?
-          duration = ::Time.monotonic - @@collect_start
-          Crystal.trace_end @@collect_start, duration, "gc", "collect"
+          duration = Crystal::System::Time.ticks - @@collect_start
+          Crystal.trace :gc, "collect", @@collect_start, duration: duration
         when .mark_end?
-          duration = ::Time.monotonic - @@mark_start
-          Crystal.trace_end @@collect_start, duration, "gc", "collect:mark"
+          duration = Crystal::System::Time.ticks - @@mark_start
+          Crystal.trace :gc, "collect:mark", @@mark_start, duration: duration
         when .reclaim_end?
-          duration = ::Time.monotonic - @@sweep_start
-          Crystal.trace_end @@collect_start, duration, "gc", "collect:sweep"
+          duration = Crystal::System::Time.ticks - @@sweep_start
+          Crystal.trace :gc, "collect:sweep", @@sweep_start, duration: duration
         end
         @@on_collection_event.try(&.call(event_type))
       })
diff --git a/src/gc/none.cr b/src/gc/none.cr
index 92585a769cc8..6a8040703cec 100644
--- a/src/gc/none.cr
+++ b/src/gc/none.cr
@@ -9,19 +9,19 @@ module GC
 
   # :nodoc:
   def self.malloc(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, "size=%lu", size
+    Crystal.trace :gc, :malloc, size: size
     LibC.malloc(size)
   end
 
   # :nodoc:
   def self.malloc_atomic(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, "size=%lu atomic=1", size
+    Crystal.trace :gc, :malloc, size: size, atomic: 1
     LibC.malloc(size)
   end
 
   # :nodoc:
   def self.realloc(pointer : Void*, size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :realloc, "size=%lu", size
+    Crystal.trace :gc, :realloc, size: size
     LibC.realloc(pointer, size)
   end
 

From 22f5aac45e24944e3fe9b470b74b72ae238b727f Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Mon, 27 May 2024 21:00:36 +0200
Subject: [PATCH 04/18] Trace: print to file (CRYSTAL_TRACE_FILE)

---
 src/crystal/system/print_error.cr | 16 ++++++++
 src/crystal/tracing.cr            | 65 ++++++++++++++++++++++++++-----
 2 files changed, 72 insertions(+), 9 deletions(-)

diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr
index ec17f325a725..1aeea5931381 100644
--- a/src/crystal/system/print_error.cr
+++ b/src/crystal/system/print_error.cr
@@ -14,6 +14,22 @@ module Crystal::System
     {% end %}
   end
 
+  {% if flag?(:win32) %}
+    def self.print_error(bytes : Slice(UInt16)) : Nil
+      utf8 = uninitialized UInt8[256]
+      len = LibC.WideCharToMultiByte(LibC::CP_UTF8, 0, bytes, bytes.size, utf8, utf8.size, nil, nil)
+      print_error utf8.to_slice[0...len]
+    end
+  {% end %}
+
+  def self.print(handle : FileDescriptor::Handle, bytes : Bytes) : Nil
+    {% if flag?(:unix) || flag?(:wasm32) %}
+      LibC.write handle, bytes, bytes.size
+    {% elsif flag?(:win32) %}
+      LibC.WriteFile(Pointer(FileDescriptor::Handle).new(handle), bytes, bytes.size, out _, nil)
+    {% end %}
+  end
+
   # Minimal drop-in replacement for C `printf` function. Yields successive
   # non-empty `Bytes` to the block, which should do the actual printing.
   #
diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index 3c50b4395ee1..f6bc9fcbb9a1 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -60,6 +60,8 @@ module Crystal
       @@sections = Section::None
       @@startup_tick = 0_u64
 
+      @@handle = uninitialized System::FileDescriptor::Handle
+
       @[AlwaysInline]
       def self.enabled?(section : Section) : Bool
         @@sections.includes?(section)
@@ -70,31 +72,75 @@ module Crystal
         @@startup_tick
       end
 
-      # Setups tracing, parsing the `CRYSTAL_TRACE` environment variable to
-      # enable the sections to trace (`gc` and/or `sched`).
+      # Setup tracing.
+      #
+      # Parses the `CRYSTAL_TRACE` environment variable to enable the sections
+      # to trace. See `Section`. By default no sections are enabled.
+      #
+      # Parses the `CRYSTAL_TRACE_FILE` environment variable to open the trace
+      # file to write to. Exits with an error message when the file can't be
+      # opened, created or truncated. Uses the standard error when unspecified.
       #
       # This should be the first thing called in main, maybe even before the GC
       # itself is initialized. The function assumes neither the GC nor ENV nor
       # anything is available and musn't allocate into the GC HEAP.
       def self.init
         @@sections = Section::None
-        @@startup_tick = ::Crystal::System::Time.ticks
+        @@startup_tick = System::Time.ticks
 
         {% if flag?(:win32) %}
           buf = uninitialized UInt16[256]
+
           name = UInt16.static_array({% for chr in "CRYSTAL_TRACE".chars %}{{chr.ord}}, {% end %} 0)
           len = LibC.GetEnvironmentVariableW(name, buf, buf.size)
-          debug = buf.to_slice[0...len] if len > 0
+          parse_sections(buf.to_slice[0...len]) if len > 0
+
+          name = UInt16.static_array({% for chr in "CRYSTAL_TRACE_FILE".chars %}{{chr.ord}}, {% end %} 0)
+          len = LibC.GetEnvironmentVariableW(name, buf, buf.size)
+          if len > 0
+            @@handle = open_trace_file(buf.to_slice[0...len])
+          else
+            @@handle = LibC.GetStdHandle(LibC::STD_ERROR_HANDLE).address
+          end
         {% else %}
           if ptr = LibC.getenv("CRYSTAL_TRACE")
             len = LibC.strlen(ptr)
-            debug = Slice.new(ptr, len) if len > 0
+            parse_sections(Slice.new(ptr, len)) if len > 0
+          end
+
+          if (ptr = LibC.getenv("CRYSTAL_TRACE_FILE")) && (LibC.strlen(ptr) > 0)
+            @@handle = open_trace_file(ptr)
+          else
+            @@handle = 2
           end
         {% end %}
+      end
 
-        return unless debug
+      private def self.open_trace_file(filename)
+        {% if flag?(:win32) %}
+          handle = LibC.CreateFileW(filename, LibC::FILE_GENERIC_WRITE, LibC::DEFAULT_SHARE_MODE, nil, LibC::CREATE_ALWAYS, LibC::FILE_ATTRIBUTE_NORMAL, LibC::HANDLE.null)
+          return handle.address unless handle == LibC::HANDLE.new(-1) # constant LibC::INVALID_HANDLE_VALUE doesn't exist (yet)
+
+          error = uninitialized UInt16[256]
+          len = LibC.FormatMessageW(LibC::FORMAT_MESSAGE_FROM_SYSTEM, nil, WinError.value, 0, error, error.size, nil)
 
-        each_token(debug) do |token|
+          System.print_error "ERROR: failed to open "
+          System.print_error filename
+          System.print_error " for writing: "
+          System.print_error error.to_slice[0...len]
+          System.print_error "\n"
+        {% else %}
+          fd = LibC.open(filename, LibC::O_CREAT | LibC::O_WRONLY | LibC::O_TRUNC | LibC::O_CLOEXEC, 0o644)
+          return fd unless fd < 0
+
+          LibC.dprintf(2, "ERROR: failed to open %s for writing: %s\n", filename, LibC.strerror(Errno.value))
+        {% end %}
+
+        LibC._exit(1)
+      end
+
+      private def self.parse_sections(bytes)
+        each_token(bytes) do |token|
           \{% begin %}
             case token
             \{% for name in Section.constants %}
@@ -115,7 +161,7 @@ module Crystal
       end
 
       # :nodoc:
-      def self.log(section : String, operation : String, time : UInt64, **metadata)
+      def self.log(section : String, operation : String, time : UInt64, **metadata) : Nil
         buf = BufferIO(512).new
         buf.write section
         buf.write "."
@@ -155,7 +201,8 @@ module Crystal
         end
 
         buf.write "\n"
-        System.print_error(buf.to_slice)
+        # System.print_error(buf.to_slice)
+        System.print(@@handle, buf.to_slice)
       end
     end
 

From d28e6cefa5421d5ed627c13637039c8a7e426c92 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Mon, 3 Jun 2024 11:16:47 +0200
Subject: [PATCH 05/18] Fix: Crystal::Tracing.init shall return nil

---
 src/crystal/tracing.cr | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index f6bc9fcbb9a1..e23d4b8946b0 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -84,7 +84,7 @@ module Crystal
       # This should be the first thing called in main, maybe even before the GC
       # itself is initialized. The function assumes neither the GC nor ENV nor
       # anything is available and musn't allocate into the GC HEAP.
-      def self.init
+      def self.init : Nil
         @@sections = Section::None
         @@startup_tick = System::Time.ticks
 

From 149f3d4373ddce4af747ed58d4ebbd8d6c25e284 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Tue, 4 Jun 2024 09:44:40 +0200
Subject: [PATCH 06/18] Prefer System.printf_error over LibC.dprintf

---
 src/crystal/tracing.cr | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index e23d4b8946b0..f91753003dbc 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -119,11 +119,13 @@ module Crystal
       private def self.open_trace_file(filename)
         {% if flag?(:win32) %}
           handle = LibC.CreateFileW(filename, LibC::FILE_GENERIC_WRITE, LibC::DEFAULT_SHARE_MODE, nil, LibC::CREATE_ALWAYS, LibC::FILE_ATTRIBUTE_NORMAL, LibC::HANDLE.null)
-          return handle.address unless handle == LibC::HANDLE.new(-1) # constant LibC::INVALID_HANDLE_VALUE doesn't exist (yet)
+          # not using LibC::INVALID_HANDLE_VALUE because it doesn't exist (yet)
+          return handle.address unless handle == LibC::HANDLE.new(-1)
 
           error = uninitialized UInt16[256]
           len = LibC.FormatMessageW(LibC::FORMAT_MESSAGE_FROM_SYSTEM, nil, WinError.value, 0, error, error.size, nil)
 
+          # not using printf because filename and error are UTF-16 slices:
           System.print_error "ERROR: failed to open "
           System.print_error filename
           System.print_error " for writing: "
@@ -133,7 +135,7 @@ module Crystal
           fd = LibC.open(filename, LibC::O_CREAT | LibC::O_WRONLY | LibC::O_TRUNC | LibC::O_CLOEXEC, 0o644)
           return fd unless fd < 0
 
-          LibC.dprintf(2, "ERROR: failed to open %s for writing: %s\n", filename, LibC.strerror(Errno.value))
+          System.print_error "ERROR: failed to open %s for writing: %s\n", filename, LibC.strerror(Errno.value)
         {% end %}
 
         LibC._exit(1)

From c8fd378e8e970ce348de221dd51649679b89fc9c Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Tue, 4 Jun 2024 09:45:43 +0200
Subject: [PATCH 07/18] Fix: no need to prefix the Crystal namespace

---
 src/crystal/tracing.cr | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index f91753003dbc..1492b8b8925f 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -35,15 +35,15 @@ module Crystal
 
         def write(ptr : Pointer) : Nil
           write "0x"
-          Crystal::System.to_int_slice(ptr.address, 16, true, 2) { |bytes| write(bytes) }
+          System.to_int_slice(ptr.address, 16, true, 2) { |bytes| write(bytes) }
         end
 
         def write(int : Int::Signed) : Nil
-          Crystal::System.to_int_slice(int, 10, true, 2) { |bytes| write(bytes) }
+          System.to_int_slice(int, 10, true, 2) { |bytes| write(bytes) }
         end
 
         def write(uint : Int::Unsigned) : Nil
-          Crystal::System.to_int_slice(uint, 10, false, 2) { |bytes| write(bytes) }
+          System.to_int_slice(uint, 10, false, 2) { |bytes| write(bytes) }
         end
 
         def to_slice : Bytes

From cbb904fabeac9d134f50c467d79c245f83ec6455 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Tue, 4 Jun 2024 09:46:07 +0200
Subject: [PATCH 08/18] Fix: remove unused @@startup_tick

---
 src/crystal/tracing.cr | 8 --------
 1 file changed, 8 deletions(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index 1492b8b8925f..2ae5f2e3b79f 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -58,8 +58,6 @@ module Crystal
       end
 
       @@sections = Section::None
-      @@startup_tick = 0_u64
-
       @@handle = uninitialized System::FileDescriptor::Handle
 
       @[AlwaysInline]
@@ -67,11 +65,6 @@ module Crystal
         @@sections.includes?(section)
       end
 
-      @[AlwaysInline]
-      def self.startup_tick : UInt64
-        @@startup_tick
-      end
-
       # Setup tracing.
       #
       # Parses the `CRYSTAL_TRACE` environment variable to enable the sections
@@ -86,7 +79,6 @@ module Crystal
       # anything is available and musn't allocate into the GC HEAP.
       def self.init : Nil
         @@sections = Section::None
-        @@startup_tick = System::Time.ticks
 
         {% if flag?(:win32) %}
           buf = uninitialized UInt16[256]

From 379b4a55542e0853be9d290e89cb14550f8e59ea Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Tue, 4 Jun 2024 09:49:49 +0200
Subject: [PATCH 09/18] fixup! Trace: print to file (CRYSTAL_TRACE_FILE)

---
 src/crystal/system/print_error.cr | 1 +
 1 file changed, 1 insertion(+)

diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr
index 1aeea5931381..6a6ef3cf4a5e 100644
--- a/src/crystal/system/print_error.cr
+++ b/src/crystal/system/print_error.cr
@@ -15,6 +15,7 @@ module Crystal::System
   end
 
   {% if flag?(:win32) %}
+    # Helper to print wide char slices (UTF-16) from the Win32 API as multibyte (UTF-8).
     def self.print_error(bytes : Slice(UInt16)) : Nil
       utf8 = uninitialized UInt8[256]
       len = LibC.WideCharToMultiByte(LibC::CP_UTF8, 0, bytes, bytes.size, utf8, utf8.size, nil, nil)

From 5541f6e58df1f9e98993f8b577ac20f2884ad8ab Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 12:54:27 +0200
Subject: [PATCH 10/18] Fix: leverage String.each_utf16_char instead of
 external C call

---
 src/crystal/system/print_error.cr | 22 ++++++++++++++++++----
 1 file changed, 18 insertions(+), 4 deletions(-)

diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr
index 6a6ef3cf4a5e..40361e537e45 100644
--- a/src/crystal/system/print_error.cr
+++ b/src/crystal/system/print_error.cr
@@ -15,11 +15,25 @@ module Crystal::System
   end
 
   {% if flag?(:win32) %}
-    # Helper to print wide char slices (UTF-16) from the Win32 API as multibyte (UTF-8).
+    # Print a UTF-16 slice as multibyte (UTF-8).
     def self.print_error(bytes : Slice(UInt16)) : Nil
-      utf8 = uninitialized UInt8[256]
-      len = LibC.WideCharToMultiByte(LibC::CP_UTF8, 0, bytes, bytes.size, utf8, utf8.size, nil, nil)
-      print_error utf8.to_slice[0...len]
+      utf8 = uninitialized UInt8[512]
+      len = 0
+
+      String.each_utf16_char(bytes) do |char|
+        # avoid buffer overun and splitting an unicode char
+        if len > utf8.size - char.bytesize
+          print_error utf8.to_slice
+          len = 0
+        end
+
+        char.each_byte do |byte]
+          utf8.to_unsafe[len] = byte
+          len &+= 1
+        end
+      end
+
+      print_error utf8.to_slice[0...len] if len > 0
     end
   {% end %}
 

From 11faaa39d82f0ed057892975d74b2d6a88170dca Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 13:19:47 +0200
Subject: [PATCH 11/18] Apply code review suggestion

---
 src/crystal/tracing.cr | 1 -
 1 file changed, 1 deletion(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index 2ae5f2e3b79f..432f0aecd53a 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -195,7 +195,6 @@ module Crystal
         end
 
         buf.write "\n"
-        # System.print_error(buf.to_slice)
         System.print(@@handle, buf.to_slice)
       end
     end

From d214022de7f7b438da5228547e0b5cca7861f1ed Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 13:18:57 +0200
Subject: [PATCH 12/18] Replace macro with a couple methods

---
 src/concurrent.cr        |  2 +-
 src/crystal/scheduler.cr | 10 ++---
 src/crystal/tracing.cr   | 80 ++++++++++++++++++++++++++--------------
 src/gc/boehm.cr          |  8 ++--
 src/gc/none.cr           |  8 ++--
 5 files changed, 66 insertions(+), 42 deletions(-)

diff --git a/src/concurrent.cr b/src/concurrent.cr
index b9eee6ea7aa2..6f3a58291a22 100644
--- a/src/concurrent.cr
+++ b/src/concurrent.cr
@@ -60,7 +60,7 @@ end
 # ```
 def spawn(*, name : String? = nil, same_thread = false, &block)
   fiber = Fiber.new(name, &block)
-  Crystal.trace :sched, :spawn, fiber: fiber
+  Crystal.trace :sched, "spawn", fiber: fiber
   {% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %}
   fiber.enqueue
   fiber
diff --git a/src/crystal/scheduler.cr b/src/crystal/scheduler.cr
index 193197bdb712..d3634e9aea6a 100644
--- a/src/crystal/scheduler.cr
+++ b/src/crystal/scheduler.cr
@@ -25,7 +25,7 @@ class Crystal::Scheduler
   end
 
   def self.enqueue(fiber : Fiber) : Nil
-    Crystal.trace :sched, :enqueue, fiber: fiber do
+    Crystal.trace :sched, "enqueue", fiber: fiber do
       thread = Thread.current
       scheduler = thread.scheduler
 
@@ -51,7 +51,7 @@ class Crystal::Scheduler
   end
 
   def self.reschedule : Nil
-    Crystal.trace :sched, :reschedule
+    Crystal.trace :sched, "reschedule"
     Thread.current.scheduler.reschedule
   end
 
@@ -61,12 +61,12 @@ class Crystal::Scheduler
   end
 
   def self.sleep(time : Time::Span) : Nil
-    Crystal.trace :sched, :sleep, for: time.total_nanoseconds.to_i64!
+    Crystal.trace :sched, "sleep", for: time.total_nanoseconds.to_i64!
     Thread.current.scheduler.sleep(time)
   end
 
   def self.yield : Nil
-    Crystal.trace :sched, :yield
+    Crystal.trace :sched, "yield"
 
     # TODO: Fiber switching and libevent for wasm32
     {% unless flag?(:wasm32) %}
@@ -115,7 +115,7 @@ class Crystal::Scheduler
   end
 
   protected def resume(fiber : Fiber) : Nil
-    Crystal.trace :sched, :resume, fiber: fiber
+    Crystal.trace :sched, "resume", fiber: fiber
     validate_resumable(fiber)
 
     {% if flag?(:preview_mt) %}
diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index 432f0aecd53a..e513e19c2b4e 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -1,4 +1,29 @@
 module Crystal
+  # :nodoc:
+  module Tracing
+    @[Flags]
+    enum Section
+      Gc
+      Sched
+
+      # Override Enum#to_s to return static strings. Doesn't consider the enum
+      # has having the flags annotation, since we only need to translate
+      # `Section::Gc` as `"gc"` in `Crystal.trace`.
+      def to_s : String
+        {% begin %}
+          case self
+          {% for constant in @type.constants %}
+            when {{constant}}
+              {{constant.id.underscore.stringify}}
+          {% end %}
+          else
+            "???"
+          end
+        {% end %}
+      end
+    end
+  end
+
   {% if flag?(:tracing) %}
     # :nodoc:
     module Tracing
@@ -51,12 +76,6 @@ module Crystal
         end
       end
 
-      @[Flags]
-      enum Section
-        Gc
-        Sched
-      end
-
       @@sections = Section::None
       @@handle = uninitialized System::FileDescriptor::Handle
 
@@ -155,6 +174,14 @@ module Crystal
       end
 
       # :nodoc:
+      #
+      # Formats and prints a log message to stderr. The generated message is
+      # limited to 512 bytes (PIPE_BUF) after which it will be truncated. Being
+      # below PIPE_BUF the message shall be written atomically to stderr,
+      # avoiding interleaved or smashed traces from multiple threads.
+      #
+      # Windows may not have the same guarantees but the buffering should limit
+      # these from happening.
       def self.log(section : String, operation : String, time : UInt64, **metadata) : Nil
         buf = BufferIO(512).new
         buf.write section
@@ -199,27 +226,21 @@ module Crystal
       end
     end
 
-    # Formats and prints a log message to stderr. The generated message is
-    # limited to 512 bytes (PIPE_BUF) after which it will be truncated. Being
-    # below PIPE_BUF the message shall be written atomically to stderr,
-    # avoiding interleaved or smashed traces from multiple threads.
-    #
-    # Windows may not have the same guarantees but the buffering should limit
-    # these from happening.
-    macro trace(section, operation, tick = nil, **metadata, &block)
-      if ::Crystal::Tracing.enabled?(\{{section}})
-        %tick = \{{tick}} || ::Crystal::System::Time.ticks
-        \{% if block %}
-          %ret = \{{yield}}
-          %duration = ::Crystal::System::Time.ticks - %tick
-          ::Crystal::Tracing.log(\{{section.id.stringify}}, \{{operation.id.stringify}}, %tick, duration: %duration, \{{metadata.double_splat}})
-          %ret
-        \{% else %}
-          ::Crystal::Tracing.log(\{{section.id.stringify}}, \{{operation.id.stringify}}, %tick, \{{metadata.double_splat}})
-          nil
-        \{% end %}
+    def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata, &)
+      if Tracing.enabled?(section)
+        time ||= System::Time.ticks
+        yield.tap do
+          duration = System::Time.ticks - time
+          Tracing.log(section.to_s, operation, time, **metadata, duration: duration)
+        end
       else
-        \{{yield}}
+        yield
+      end
+    end
+
+    def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata) : Nil
+      if Tracing.enabled?(section)
+        Tracing.log(section.to_s, operation, time || System::Time.ticks, **metadata)
       end
     end
   {% else %}
@@ -236,8 +257,11 @@ module Crystal
       end
     end
 
-    macro trace(section, operation, **metadata, &block)
-      \{{yield}}
+    def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata, &)
+      yield
+    end
+
+    def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata)
     end
   {% end %}
 end
diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr
index 9b9b1ce141ef..e5bb5cf5f52d 100644
--- a/src/gc/boehm.cr
+++ b/src/gc/boehm.cr
@@ -170,21 +170,21 @@ module GC
 
   # :nodoc:
   def self.malloc(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, size: size do
+    Crystal.trace :gc, "malloc", size: size do
       LibGC.malloc(size)
     end
   end
 
   # :nodoc:
   def self.malloc_atomic(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, size: size, atomic: 1 do
+    Crystal.trace :gc, "malloc", size: size, atomic: 1 do
       LibGC.malloc_atomic(size)
     end
   end
 
   # :nodoc:
   def self.realloc(ptr : Void*, size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :realloc, size: size do
+    Crystal.trace :gc, "realloc", size: size do
       LibGC.realloc(ptr, size)
     end
   end
@@ -230,7 +230,7 @@ module GC
       @@on_heap_resize = LibGC.get_on_heap_resize
 
       LibGC.set_on_heap_resize(->(new_size : LibGC::Word) {
-        Crystal.trace :gc, :heap_resize, size: new_size
+        Crystal.trace :gc, "heap_resize", size: new_size
         @@on_heap_resize.try(&.call(new_size))
       })
     end
diff --git a/src/gc/none.cr b/src/gc/none.cr
index 6a8040703cec..1121caef1bf4 100644
--- a/src/gc/none.cr
+++ b/src/gc/none.cr
@@ -9,19 +9,19 @@ module GC
 
   # :nodoc:
   def self.malloc(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, size: size
+    Crystal.trace :gc, "malloc", size: size
     LibC.malloc(size)
   end
 
   # :nodoc:
   def self.malloc_atomic(size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :malloc, size: size, atomic: 1
+    Crystal.trace :gc, "malloc", size: size, atomic: 1
     LibC.malloc(size)
   end
 
   # :nodoc:
   def self.realloc(pointer : Void*, size : LibC::SizeT) : Void*
-    Crystal.trace :gc, :realloc, size: size
+    Crystal.trace :gc, "realloc", size: size
     LibC.realloc(pointer, size)
   end
 
@@ -35,7 +35,7 @@ module GC
   end
 
   def self.free(pointer : Void*) : Nil
-    Crystal.trace :gc, :free
+    Crystal.trace :gc, "free"
     LibC.free(pointer)
   end
 

From 9a9025c7c53a639038b6ec54dd6a7897cbe856c1 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 14:50:19 +0200
Subject: [PATCH 13/18] fixup! Fix: leverage String.each_utf16_char instead of
 external C call

---
 src/crystal/system/print_error.cr | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr
index 40361e537e45..5029b82ad2ac 100644
--- a/src/crystal/system/print_error.cr
+++ b/src/crystal/system/print_error.cr
@@ -27,7 +27,7 @@ module Crystal::System
           len = 0
         end
 
-        char.each_byte do |byte]
+        char.each_byte do |byte|
           utf8.to_unsafe[len] = byte
           len &+= 1
         end

From 9ce8adb9279d509437f261df9e9a2f72e399a9ce Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 15:07:23 +0200
Subject: [PATCH 14/18] fixup! Replace macro with a couple methods

---
 src/gc/boehm.cr | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr
index e5bb5cf5f52d..8ccc1bb7b6e8 100644
--- a/src/gc/boehm.cr
+++ b/src/gc/boehm.cr
@@ -262,7 +262,7 @@ module GC
   {% end %}
 
   def self.collect
-    Crystal.trace :gc, :collect do
+    Crystal.trace :gc, "collect" do
       LibGC.collect
     end
   end
@@ -280,7 +280,7 @@ module GC
   end
 
   def self.free(pointer : Void*) : Nil
-    Crystal.trace :gc, :free do
+    Crystal.trace :gc, "free" do
       LibGC.free(pointer)
     end
   end

From 34ee68dcf45eb928f083cd57fdd4aa0a4a9d19fb Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 15:43:03 +0200
Subject: [PATCH 15/18] Fix: don't overload Enum#to_s (use distinct method)

---
 src/crystal/tracing.cr | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index e513e19c2b4e..ccd8468e186c 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -6,10 +6,10 @@ module Crystal
       Gc
       Sched
 
-      # Override Enum#to_s to return static strings. Doesn't consider the enum
-      # has having the flags annotation, since we only need to translate
-      # `Section::Gc` as `"gc"` in `Crystal.trace`.
-      def to_s : String
+      # Alternative to Enum#to_s that doesn't consider the enum has having the
+      # flags annotation so we can return static strings. This is used to
+      # translate `Section::Gc` as `"gc"` in `Crystal.trace` for example.
+      def id : String
         {% begin %}
           case self
           {% for constant in @type.constants %}
@@ -231,7 +231,7 @@ module Crystal
         time ||= System::Time.ticks
         yield.tap do
           duration = System::Time.ticks - time
-          Tracing.log(section.to_s, operation, time, **metadata, duration: duration)
+          Tracing.log(section.id, operation, time, **metadata, duration: duration)
         end
       else
         yield
@@ -240,7 +240,7 @@ module Crystal
 
     def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata) : Nil
       if Tracing.enabled?(section)
-        Tracing.log(section.to_s, operation, time || System::Time.ticks, **metadata)
+        Tracing.log(section.id, operation, time || System::Time.ticks, **metadata)
       end
     end
   {% else %}

From e8648efe45d4a2feadcfe6ed633d65e01b96609f Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 15:51:20 +0200
Subject: [PATCH 16/18] Fix: use Pointer::Appender in print_error(Slice(UInt8))

Fixes a bug where it'd print the whole buffer despite not necessarily
using it fully (when last char doesn't fit).

Also no longer restricts the method to Windows; it might be useful in
other cases?
---
 src/crystal/system/print_error.cr | 36 +++++++++++++++----------------
 1 file changed, 18 insertions(+), 18 deletions(-)

diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr
index 5029b82ad2ac..796579bf256a 100644
--- a/src/crystal/system/print_error.cr
+++ b/src/crystal/system/print_error.cr
@@ -14,28 +14,28 @@ module Crystal::System
     {% end %}
   end
 
-  {% if flag?(:win32) %}
-    # Print a UTF-16 slice as multibyte (UTF-8).
-    def self.print_error(bytes : Slice(UInt16)) : Nil
-      utf8 = uninitialized UInt8[512]
-      len = 0
-
-      String.each_utf16_char(bytes) do |char|
-        # avoid buffer overun and splitting an unicode char
-        if len > utf8.size - char.bytesize
-          print_error utf8.to_slice
-          len = 0
-        end
+  # Print a UTF-16 slice as UTF-8 directly to stderr. Useful on Windows to print
+  # strings returned from the unicode variant of the Win32 API.
+  def self.print_error(bytes : Slice(UInt16)) : Nil
+    utf8 = uninitialized UInt8[512]
+    appender = utf8.to_unsafe.appender
+
+    String.each_utf16_char(bytes) do |char|
+      if appender.size > utf8.size - char.bytesize
+        # buffer is full (char won't fit)
+        print_error utf8.to_slice[0...appender.size]
+        appender = utf8.to_unsafe.appender
+      end
 
-        char.each_byte do |byte|
-          utf8.to_unsafe[len] = byte
-          len &+= 1
-        end
+      char.each_byte do |byte|
+        appender << byte
       end
+    end
 
-      print_error utf8.to_slice[0...len] if len > 0
+    if appender.size > 0
+      print_error utf8.to_slice[0...appender.size]
     end
-  {% end %}
+  end
 
   def self.print(handle : FileDescriptor::Handle, bytes : Bytes) : Nil
     {% if flag?(:unix) || flag?(:wasm32) %}

From 5b65aad430c8b77c298341a5846f220dc98cd25a Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 15:57:15 +0200
Subject: [PATCH 17/18] Fix: use ensure instead of tap so we still print the
 trace

---
 src/crystal/tracing.cr | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index ccd8468e186c..f56cef427628 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -229,7 +229,9 @@ module Crystal
     def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata, &)
       if Tracing.enabled?(section)
         time ||= System::Time.ticks
-        yield.tap do
+        begin
+          yield
+        ensure
           duration = System::Time.ticks - time
           Tracing.log(section.id, operation, time, **metadata, duration: duration)
         end

From 1dfe3c56146e7e15ba317cc191a0c28a0e78a825 Mon Sep 17 00:00:00 2001
From: Julien Portalier <julien@portalier.com>
Date: Thu, 13 Jun 2024 17:25:07 +0200
Subject: [PATCH 18/18] Refactor: Section.from_id(slice) and Section#to_id

---
 src/crystal/tracing.cr | 53 ++++++++++++++++++++++--------------------
 1 file changed, 28 insertions(+), 25 deletions(-)

diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr
index f56cef427628..708956ad8feb 100644
--- a/src/crystal/tracing.cr
+++ b/src/crystal/tracing.cr
@@ -3,18 +3,28 @@ module Crystal
   module Tracing
     @[Flags]
     enum Section
-      Gc
+      GC
       Sched
 
-      # Alternative to Enum#to_s that doesn't consider the enum has having the
-      # flags annotation so we can return static strings. This is used to
-      # translate `Section::Gc` as `"gc"` in `Crystal.trace` for example.
-      def id : String
+      def self.from_id(slice) : self
+        {% begin %}
+          case slice
+            {% for name in @type.constants %}
+              when {{name.underscore.stringify}}.to_slice
+                {{name}}
+            {% end %}
+          else
+            None
+          end
+        {% end %}
+      end
+
+      def to_id : String
         {% begin %}
           case self
-          {% for constant in @type.constants %}
-            when {{constant}}
-              {{constant.id.underscore.stringify}}
+          {% for name in @type.constants %}
+            when {{name}}
+              {{name.underscore.stringify}}
           {% end %}
           else
             "???"
@@ -152,25 +162,18 @@ module Crystal
         LibC._exit(1)
       end
 
-      private def self.parse_sections(bytes)
-        each_token(bytes) do |token|
-          \{% begin %}
-            case token
-            \{% for name in Section.constants %}
-              when \{{name.downcase.id.stringify}}.to_slice
-                @@sections |= Section::\{{name.id}}
-            \{% end %}
-            end
-          \{% end %}
+      private def self.parse_sections(slice)
+        each_token(slice) do |token|
+          @@sections |= Section.from_id(token)
         end
       end
 
-      private def self.each_token(bytes, delim = ',', &)
-        while e = bytes.index(delim.ord)
-          yield bytes[0, e]
-          bytes = bytes[(e + 1)..]
+      private def self.each_token(slice, delim = ',', &)
+        while e = slice.index(delim.ord)
+          yield slice[0, e]
+          slice = slice[(e + 1)..]
         end
-        yield bytes[0..] unless bytes.size == 0
+        yield slice[0..] unless slice.size == 0
       end
 
       # :nodoc:
@@ -233,7 +236,7 @@ module Crystal
           yield
         ensure
           duration = System::Time.ticks - time
-          Tracing.log(section.id, operation, time, **metadata, duration: duration)
+          Tracing.log(section.to_id, operation, time, **metadata, duration: duration)
         end
       else
         yield
@@ -242,7 +245,7 @@ module Crystal
 
     def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata) : Nil
       if Tracing.enabled?(section)
-        Tracing.log(section.id, operation, time || System::Time.ticks, **metadata)
+        Tracing.log(section.to_id, operation, time || System::Time.ticks, **metadata)
       end
     end
   {% else %}