Add Crystal::Tracing for runtime tracing

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

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) %}

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

src/gc/boehm.cr

@@ -170,21 +170,21 @@
 
   # :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 @@
       @@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
@@ -280,7 +280,7 @@
   end
 
   def self.free(pointer : Void*) : Nil
     Crystal.trace :gc, :free do
       LibGC.free(pointer)
     end
   end

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