Add Crystal::Tracing for runtime tracing (#14659)

Implements tracing of the garbage collector and the scheduler as per #14618

Tracing is enabled by compiling with `-Dtracing` then individual tracing must be enabled at runtime with the `CRYSTAL_TRACE` environment variable that is a comma separated list of sections to enable, for example:

- ` ` (empty value) or `none` to disable any tracing (default)
- `gc`
- `sched`
- `gc,sched`
- `all` to enable everything

The traces are printed to the standard error by default, but this can be changed at runtime with the `CRYSTAL_TRACE_FILE` environment variable. For example `trace.log`. You can also redirect the standard error to a file (e.g. `2> trace.log` on UNIX shell).

Example tracing calls:

    Crystal.trace :sched, "spawn", fiber: fiber
    Crystal.trace :gc, "malloc", size: size, atomic: 1

**Technical note:** tracing happens before the stdlib is initialized, so the implementation must rely on some `LibC` methods directly (i.e. read environment variable, write to file descriptor) and can't use the core/stdlib abstractions.

Co-authored-by: Johannes Müller <straightshoota@gmail.com>

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,37 @@ module Crystal::System
     {% end %}
   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|
+        appender << byte
+      end
+    end
+
+    if appender.size > 0
+      print_error utf8.to_slice[0...appender.size]
+    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 +140,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