Add Crystal::Tracing for runtime tracing

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: fiber
   {% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %}
   fiber.enqueue
   fiber

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 =

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: fiber 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, for: 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: fiber
     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

src/crystal/system/print_error.cr

@@ -14,6 +14,23 @@ module Crystal::System
     {% end %}
   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)
+      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.
   #
@@ -109,7 +126,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

src/crystal/tracing.cr

@@ -0,0 +1,244 @@
+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 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"
+          System.to_int_slice(ptr.address, 16, true, 2) { |bytes| write(bytes) }
+        end
+
+        def write(int : Int::Signed) : Nil
+          System.to_int_slice(int, 10, true, 2) { |bytes| write(bytes) }
+        end
+
+        def write(uint : Int::Unsigned) : Nil
+          System.to_int_slice(uint, 10, false, 2) { |bytes| write(bytes) }
+        end
+
+        def to_slice : Bytes
+          Bytes.new(@buf.to_unsafe, @size)
+        end
+      end
+
+      @[Flags]
+      enum Section
+        Gc
+        Sched
+      end
+
+      @@sections = Section::None
+      @@handle = uninitialized System::FileDescriptor::Handle
+
+      @[AlwaysInline]
+      def self.enabled?(section : Section) : Bool
+        @@sections.includes?(section)
+      end
+
+      # 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 : Nil
+        @@sections = Section::None
+
+        {% 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)
+          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)
+            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
+
+      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)
+          # 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: "
+          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
+
+          System.print_error "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 %}
+              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
+
+      # :nodoc:
+      def self.log(section : String, operation : String, time : UInt64, **metadata) : Nil
+        buf = BufferIO(512).new
+        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)
+        System.print(@@handle, buf.to_slice)
+      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 %}
+      else
+        \{{yield}}
+      end
+    end
+  {% else %}
+    # :nodoc:
+    module Tracing
+      def self.init
+      end
+
+      def self.enabled?(section)
+        false
+      end
+
+      def self.log(section : String, operation : String, time : UInt64, **metadata)
+      end
+    end
+
+    macro trace(section, operation, **metadata, &block)
+      \{{yield}}
+    end
+  {% end %}
+end