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,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