diff --git a/src/concurrent.cr b/src/concurrent.cr index af2f0aecf736..6f3a58291a22 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: fiber {% 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..d3634e9aea6a 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: 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 diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr index f58bef1c4ff6..796579bf256a 100644 --- a/src/crystal/system/print_error.cr +++ b/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 diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr new file mode 100644 index 000000000000..708956ad8feb --- /dev/null +++ b/src/crystal/tracing.cr @@ -0,0 +1,272 @@ +module Crystal + # :nodoc: + module Tracing + @[Flags] + enum Section + GC + Sched + + 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 name in @type.constants %} + when {{name}} + {{name.underscore.stringify}} + {% end %} + else + "???" + end + {% end %} + end + end + end + + {% 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 + + @@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(slice) + each_token(slice) do |token| + @@sections |= Section.from_id(token) + end + end + + private def self.each_token(slice, delim = ',', &) + while e = slice.index(delim.ord) + yield slice[0, e] + slice = slice[(e + 1)..] + end + yield slice[0..] unless slice.size == 0 + 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 + 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(@@handle, buf.to_slice) + end + end + + def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata, &) + if Tracing.enabled?(section) + time ||= System::Time.ticks + begin + yield + ensure + duration = System::Time.ticks - time + Tracing.log(section.to_id, operation, time, **metadata, duration: duration) + end + else + yield + end + end + + def self.trace(section : Tracing::Section, operation : String, time : UInt64? = nil, **metadata) : Nil + if Tracing.enabled?(section) + Tracing.log(section.to_id, operation, time || System::Time.ticks, **metadata) + 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 + + 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 29ae825adab1..8ccc1bb7b6e8 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: 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: size, atomic: 1 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: 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 = 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: 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 = Crystal::System::Time.ticks + when .mark_start? + @@mark_start = Crystal::System::Time.ticks + when .reclaim_start? + @@sweep_start = Crystal::System::Time.ticks + when .end? + duration = Crystal::System::Time.ticks - @@collect_start + Crystal.trace :gc, "collect", @@collect_start, duration: duration + when .mark_end? + duration = Crystal::System::Time.ticks - @@mark_start + Crystal.trace :gc, "collect:mark", @@mark_start, duration: duration + when .reclaim_end? + duration = Crystal::System::Time.ticks - @@sweep_start + Crystal.trace :gc, "collect:sweep", @@sweep_start, duration: duration + 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..1121caef1bf4 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: size LibC.malloc(size) end # :nodoc: def self.malloc_atomic(size : LibC::SizeT) : Void* + 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 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