From bbd7ce9d7cdb517c6637551ebd9b9fabd130d0f4 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Wed, 27 Dec 2023 11:11:06 +0100 Subject: [PATCH 01/20] Initial tracing of GC and scheduler operations --- src/concurrent.cr | 2 + src/crystal/scheduler.cr | 39 ++++++++----- src/crystal/system/thread.cr | 14 +++++ src/crystal/system/unix/pthread.cr | 14 +++++ src/crystal/tracing.cr | 80 +++++++++++++++++++++++++++ src/gc/boehm.cr | 89 ++++++++++++++++++++++++++++-- src/gc/none.cr | 6 ++ 7 files changed, 224 insertions(+), 20 deletions(-) create mode 100644 src/crystal/tracing.cr diff --git a/src/concurrent.cr b/src/concurrent.cr index af2f0aecf736..44821a67f387 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=%lx", fiber.object_id {% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %} fiber.enqueue fiber diff --git a/src/crystal/scheduler.cr b/src/crystal/scheduler.cr index c86d04309b14..53dbf153f196 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=%lx", fiber.object_id 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", "%.9f", time.to_f 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=%lx", fiber.object_id 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_once + Crystal.trace "sched", "event_loop" do + @event_loop.run_once + 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/thread.cr b/src/crystal/system/thread.cr index e6627538112d..932a637d6507 100644 --- a/src/crystal/system/thread.cr +++ b/src/crystal/system/thread.cr @@ -100,6 +100,13 @@ class Thread Crystal::System::Thread.current_thread end + {% if flag?(:tracing) %} + # :nodoc: + def self.current? : Thread? + Crystal::System::Thread.current_thread? + end + {% end %} + # Associates the Thread object to the running system thread. protected def self.current=(current : Thread) : Thread Crystal::System::Thread.current_thread = current @@ -120,6 +127,13 @@ class Thread # :nodoc: getter scheduler : Crystal::Scheduler { Crystal::Scheduler.new(self) } + {% if flag?(:tracing) %} + # :nodoc: + def scheduler? : ::Crystal::Scheduler? + @scheduler + end + {% end %} + protected def start Thread.threads.push(self) Thread.current = self diff --git a/src/crystal/system/unix/pthread.cr b/src/crystal/system/unix/pthread.cr index f96d0bbf75ba..51fd7fff3aa1 100644 --- a/src/crystal/system/unix/pthread.cr +++ b/src/crystal/system/unix/pthread.cr @@ -55,6 +55,14 @@ module Crystal::System::Thread end end + {% if flag?(:tracing) %} + def self.current_thread? : ::Thread? + if ptr = LibC.pthread_getspecific(@@current_key) + ptr.as(::Thread) + end + end + {% end %} + def self.current_thread=(thread : ::Thread) ret = LibC.pthread_setspecific(@@current_key, thread.as(Void*)) raise RuntimeError.from_os_error("pthread_setspecific", Errno.new(ret)) unless ret == 0 @@ -63,6 +71,12 @@ module Crystal::System::Thread {% else %} @[ThreadLocal] class_property current_thread : ::Thread { ::Thread.new } + + {% if flag?(:tracing) %} + def self.current_thread? : ::Thread? + @@current_thread + end + {% end %} {% end %} private def system_join : Exception? diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr new file mode 100644 index 000000000000..dc267cd859fc --- /dev/null +++ b/src/crystal/tracing.cr @@ -0,0 +1,80 @@ +module Crystal + {% if flag?(:tracing) %} + # Formats and prints a log message to STDERR. The generated message is + # limited to 511 bytes after which it will be truncated. + # + # Doesn't use `dprintf(2)` that may do multiple writes to fd, leading to + # smashed log lines with multithreading, we prefer to use `snprintf(2)` with + # a stack allocated buffer that has a maximum size of PIPE_BUF bytes minus + # one byte for the terminating null byte. + # + # Eventually writes to STDERR in a single write operation that should be + # atomic since the buffer is smaller than of equal to PIPE_BUF, on POSIX + # platforms at least. + # + # Doesn't continue to write on partial writes (e.g. interrupted by a signal) + # as the output could be smashed with a parallel write. + def self.trace_log(format : String, *args) : Nil + buffer = uninitialized UInt8[512] + + len = LibC.snprintf(buffer, buffer.size, format, *args) + return if len == 0 + + {% if flag?(:win32) %} + # FIXME: atomicity of _write on win32? + LibC._write(2, buffer, len) + {% else %} + LibC.write(2, buffer, len) + {% end %} + end + + macro trace(section, action, format = "", *args, &block) + \{% if block %} + %start = ::Crystal::System::Time.monotonic + %ret = \{{yield}} + %stop = ::Crystal::System::Time.monotonic + %duration = { %stop[0] - %start[0], %stop[1] - %start[1] } + ::Crystal.trace_end('d', %duration, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + %ret + \{% else %} + %tick = ::Crystal::System::Time.monotonic + ::Crystal.trace_end('t', %tick, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + nil + \{% end %} + end + + macro trace_end(t, tick_or_duration, section, action, format = "", *args) + %s, %ns = \{{tick_or_duration}} + + # we may 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 are allocate (otherwise we hit infinite + # recursion): malloc -> trace -> malloc -> trace -> ... + if %thread = Thread.current? + if %scheduler = %thread.scheduler? + %fiber = %scheduler.@current + ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%d.%09d thread=%lx fiber=%lx [%s] \{{format.id}}\n", + %s, %ns, %thread, %fiber.object_id, %fiber.name || "", \{{args.splat}}) + else + # fallback: no scheduler (or not started yet?) for the current thread + ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%d.%09d thread=%lx \{{format.id}}\n", + %s, %ns, %thread, \{{args.splat}}) + end + else + # fallback: no Thread object (yet) + ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%d.%09d thread=%lx \{{format.id}}\n", + %s, %ns, Crystal::System::Thread.current_handle, \{{args.splat}}) + end + end + {% else %} + def self.trace_log(format : String, *args) + end + + macro trace(section, action, format = "", *args, &block) + \{{yield}} + end + + macro trace_end(t, tick_or_duration, section, action, format = "", *args) + end + {% end %} +end diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr index 29ae825adab1..15634ac69f2a 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,20 +170,28 @@ module GC # :nodoc: def self.malloc(size : LibC::SizeT) : Void* - LibGC.malloc(size) + Crystal.trace "gc", "malloc", "size=%ld", 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=%ld atomic=1", size 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=%ld", size do + LibGC.realloc(ptr, size) + end end def self.init : Nil + # Crystal.trace "gc", "init" + {% unless flag?(:win32) %} LibGC.set_handle_fork(1) {% end %} @@ -166,6 +200,12 @@ module GC LibGC.set_start_callback ->do GC.lock_write end + + {% if flag?(:tracing) %} + set_on_heap_resize_proc + set_on_collection_events_proc + {% 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,43 @@ module GC end end + {% if flag?(:tracing) %} + @@on_heap_resize : LibGC::OnHeapResizeProc? + @@on_collection_event : LibGC::OnCollectionEventProc? + @@collect_start_s = 0_i64 + @@collect_start_ns = 0_i32 + + 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=%lld", UInt64.new(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) { + # Crystal.trace "gc", "on_collection_event", "type=%s", event_type.to_s + case event_type + when .start? + @@collect_start_s, @@collect_start_ns = Crystal::System::Time.monotonic + when .end? + end_s, end_ns = Crystal::System::Time.monotonic + duration = { end_s - @@collect_start_s, end_ns - @@collect_start_ns } + Crystal.trace_end 'd', duration, "gc", "collect" + 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 +270,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..20a2cd9a738b 100644 --- a/src/gc/none.cr +++ b/src/gc/none.cr @@ -1,23 +1,28 @@ {% if flag?(:win32) %} require "c/process" {% end %} +require "crystal/tracing" module GC def self.init + # Crystal.trace "gc", "init" end # :nodoc: def self.malloc(size : LibC::SizeT) : Void* + Crystal.trace "gc", "malloc", "size=%ld", size LibC.malloc(size) end # :nodoc: def self.malloc_atomic(size : LibC::SizeT) : Void* + Crystal.trace "gc", "malloc", "size=%ld atomic=1", size LibC.malloc(size) end # :nodoc: def self.realloc(pointer : Void*, size : LibC::SizeT) : Void* + Crystal.trace "gc", "realloc", "size=%ld", size LibC.realloc(pointer, size) end @@ -31,6 +36,7 @@ module GC end def self.free(pointer : Void*) : Nil + Crystal.trace "gc", "free" LibC.free(pointer) end From 9de22d1965e881851fc145339a166e7420ace54b Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Wed, 27 Dec 2023 16:32:58 +0100 Subject: [PATCH 02/20] Fix: crystal tool format --- src/gc/boehm.cr | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr index 15634ac69f2a..72709ecbc607 100644 --- a/src/gc/boehm.cr +++ b/src/gc/boehm.cr @@ -115,7 +115,7 @@ lib LibGC {% end %} alias OnHeapResizeProc = Word -> - fun set_on_heap_resize = GC_set_on_heap_resize(OnHeapResizeProc); + fun set_on_heap_resize = GC_set_on_heap_resize(OnHeapResizeProc) fun get_on_heap_resize = GC_get_on_heap_resize : OnHeapResizeProc enum EventType @@ -124,10 +124,10 @@ lib LibGC MARK_END RECLAIM_START RECLAIM_END - END # COLLECTION - PRE_STOP_WORLD # STOPWORLD_BEGIN - POST_STOP_WORLD # STOPWORLD_END - PRE_START_WORLD # STARTWORLD_BEGIN + 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 @@ -135,11 +135,11 @@ lib LibGC 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 + 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 + fun get_on_thread_event = GC_get_on_thread_event : OnThreadEventProc $gc_no = GC_gc_no : Word $bytes_found = GC_bytes_found : SignedWord @@ -243,7 +243,7 @@ module GC @@collect_start_s, @@collect_start_ns = Crystal::System::Time.monotonic when .end? end_s, end_ns = Crystal::System::Time.monotonic - duration = { end_s - @@collect_start_s, end_ns - @@collect_start_ns } + duration = {end_s - @@collect_start_s, end_ns - @@collect_start_ns} Crystal.trace_end 'd', duration, "gc", "collect" end @@on_collection_event.try(&.call(event_type)) From 154d4f86ff5f85f3cc65829e8862a3c228c5a360 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Wed, 27 Dec 2023 17:04:53 +0100 Subject: [PATCH 03/20] Introduce 'crystal tool trace' command to analyze trace logs --- src/compiler/crystal/command.cr | 4 + src/compiler/crystal/command/trace.cr | 44 ++++++ src/compiler/crystal/tools/tracing.cr | 199 ++++++++++++++++++++++++++ 3 files changed, 247 insertions(+) create mode 100644 src/compiler/crystal/command/trace.cr create mode 100644 src/compiler/crystal/tools/tracing.cr diff --git a/src/compiler/crystal/command.cr b/src/compiler/crystal/command.cr index 7644f412bb8e..8019116eafaf 100644 --- a/src/compiler/crystal/command.cr +++ b/src/compiler/crystal/command.cr @@ -48,6 +48,7 @@ class Crystal::Command implementations show implementations for given call in location unreachable show methods that are never called types show type of main variables + trace analyze trace logs --help, -h show this help USAGE @@ -199,6 +200,9 @@ class Crystal::Command when "unreachable".starts_with?(tool) options.shift unreachable + when "trace".starts_with?(tool) + options.shift + trace when "--help" == tool, "-h" == tool puts COMMANDS_USAGE exit diff --git a/src/compiler/crystal/command/trace.cr b/src/compiler/crystal/command/trace.cr new file mode 100644 index 000000000000..e1e637252d42 --- /dev/null +++ b/src/compiler/crystal/command/trace.cr @@ -0,0 +1,44 @@ +class Crystal::Command + private def trace + command = "stats" + color = true + + OptionParser.parse(@options) do |opts| + opts.banner = <<-USAGE + Usage: crystal tool trace [command] [- | file or directory ...] + + Analyzes trace logs. + + If a file or directory is omitted, the 'trace.log' file in the + working directory will be used. To analyze STDIN use '-' in place + of any path arguments. + + Commands: + USAGE + + opts.on("stats", "Generate stats from a trace file (default)") do + command = "stats" + end + + opts.on("--no-color", "Disable colored output") do + color = false + end + + opts.on("-h", "--help", "Show this message") do + puts opts + exit + end + end + + input = options.first? || "trace.log" + + case command + when "stats" + if input == "-" || File.exists?(input) + Tracing::StatsGenerator.new(input, color: color).run + else + error "file '#{input}' does not exist" + end + end + end +end diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr new file mode 100644 index 000000000000..897e50aa86d6 --- /dev/null +++ b/src/compiler/crystal/tools/tracing.cr @@ -0,0 +1,199 @@ +require "colorize" + +module Crystal + module Tracing + class Values(T) + delegate :size, :sum, :min, :max, to: @values + + def initialize + @values = [] of T + end + + def <<(value) + @values << T.new(value) + end + + def average + if @values.empty? + T.new(0) + else + @values.sum / @values.size + end + end + + def stddev(mean) + zero = T.new(0) + + if @values.empty? + zero + else + variance = @values.reduce(zero) { |a, e| a + ((e - mean) ** 2) } / @values.size + Math.sqrt(variance) + end + end + + def humanize(io, value) + io << value.round(9) + end + + def to_s(io : IO) : Nil + io << "[total=" + humanize io, sum + io << " min=" + humanize io, min + io << " max=" + humanize io, max + io << " mean=" + humanize io, mean = average + io << " ±" + humanize io, stddev(mean) + io << ']' + end + end + + class Durations < Values(Float64) + def humanize(io, value) + value = value.abs + + if value >= 1 + io << value.round(2) + io << 's' + elsif value > 0.001 + io << (value * 1_000).to_i64 + io << "ms" + elsif value > 0.000_001 + io << (value * 1_000_000).to_i64 + io << "us" + else + io << (value * 1_000_000_000).to_i64 + io << "ns" + end + end + end + + class Sizes < Values(UInt64) + KILOBYTE = 1024 + MEGABYTE = 1024 * 1024 + GIGABYTE = 1024 * 1024 * 1024 + + def humanize(io, value) + value = value.abs.to_u64 + + if value >= GIGABYTE + io << (value // GIGABYTE) + io << "GB" + elsif value >= MEGABYTE + io << (value // MEGABYTE) + io << "MB" + elsif value >= KILOBYTE + io << (value // KILOBYTE) + io << "KB" + else + io << value + io << 'B' + end + end + end + + class Data + property events : Int64 + getter values : Hash(Symbol, Values(Float64)) + + def initialize + @events = 0_i64 + @values = {} of Symbol => Values(Float64) + end + + def duration + @duration ||= Durations.new + end + + def sizes + @sizes ||= Sizes.new + end + + def each(&) + yield :events, @events + + if duration = @duration + yield :duration, duration + end + + if sizes = @sizes + yield :sizes, sizes + end + + @values.each do |key, value| + yield key, value + end + end + end + + class StatsGenerator + alias Action = Hash(String, Data) + alias Section = Hash(String, Action) + + def initialize(@path : String, @color : Bool) + end + + def run + stats = Section.new do |h, k| + h[k] = Action.new do |h, k| + h[k] = Data.new + end + end + + each_event do |section, action, t, time, variables| + data = stats[section][action] + data.events += 1 + data.duration << time.to_f if t == "d" + + if section == "gc" + if action == "malloc" + if variables =~ /\bsize=(\d+)\s*/ + data.sizes << $1.to_i + end + end + end + end + + stats.each do |section, actions| + actions.each do |action, data| + Colorize.with.toggle(@color).yellow.surround(STDOUT) do + STDOUT << section << ':' << action + end + + data.each do |key, value| + STDOUT << ' ' << key << '=' + value.to_s(STDOUT) + end + + STDOUT << '\n' + end + end + end + + PARSE_TRACE_RE = /^(\w+) ([-_:\w]+) ([td])=(\d+\.\d+)\s*(.+)$/ + + private def each_event(&) + open_trace_file do |input| + while line = input.gets(chomp: true) + if line =~ PARSE_TRACE_RE + yield $1, $2, $3, $4, $5 + elsif @path != "-" + STDERR.print "WARN: invalid trace '#{line}'\n" + end + end + end + end + + private def open_trace_file(&) + if @path == "-" + yield STDIN + else + File.open(@path, "r") { |file| yield file } + end + end + end + end +end From eacf3c5d7f412e877b79a8adee4468db2efc83ac Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Wed, 27 Dec 2023 17:36:56 +0100 Subject: [PATCH 04/20] Rename to Crystal::Tracing::StatsCommand + minimal specs --- spec/compiler/crystal/tools/tracing_spec.cr | 80 +++++++++++++++++++++ src/compiler/crystal/command/trace.cr | 2 +- src/compiler/crystal/tools/tracing.cr | 27 ++++--- 3 files changed, 99 insertions(+), 10 deletions(-) create mode 100644 spec/compiler/crystal/tools/tracing_spec.cr diff --git a/spec/compiler/crystal/tools/tracing_spec.cr b/spec/compiler/crystal/tools/tracing_spec.cr new file mode 100644 index 000000000000..a43091072325 --- /dev/null +++ b/spec/compiler/crystal/tools/tracing_spec.cr @@ -0,0 +1,80 @@ +require "spec" +require "compiler/crystal/tools/tracing" +require "../../../support/tempfile" + +describe Crystal::Tracing::StatsCommand do + it "parses stdin" do + stdin = IO::Memory.new <<-TRACE + gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 + gc malloc d=0.000009074 thread=7f0ea62bd740 size=4 atomic=1 + gc malloc d=0.000000128 thread=7f0ea62bd740 size=144 + sched spawn t=102125.792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 + sched enqueue d=0.000101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 + gc malloc d=0.000000222 thread=7f0ea62bd740 size=24 + gc collect d=0.000079489 thread=7f0ea62bd740 + gc heap_resize t=102125.791993928 thread=7f0ea62bd740 size=131072 + TRACE + stdout = IO::Memory.new + stderr = IO::Memory.new + + Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run + output = stdout.to_s + output.should contain("gc:malloc events=4 duration=") + output.should contain("gc:collect events=1 duration=") + output.should contain("gc:heap_resize events=1") + output.should contain("sched:spawn events=1") + output.should contain("sched:enqueue events=1 duration=") + stderr.to_s.should be_empty + end + + it "parses file" do + stdin = IO::Memory.new "" + stdout = IO::Memory.new + stderr = IO::Memory.new + + with_tempfile("trace.log") do |path| + File.write path, <<-TRACE + gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 + gc malloc d=0.000009074 thread=7f0ea62bd740 size=4 atomic=1 + gc malloc d=0.000000222 thread=7f0ea62bd740 size=24 + gc collect d=0.000079489 thread=7f0ea62bd740 + TRACE + + Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run + output = stdout.to_s + output.should contain("gc:malloc events=3 duration=") + output.should contain("gc:collect events=1 duration=") + stderr.to_s.should be_empty + end + end + + it "warns about invalid traces" do + stdin = IO::Memory.new "" + stdout = IO::Memory.new + stderr = IO::Memory.new + + with_tempfile("trace.log") do |path| + File.write path, <<-TRACE + Using compiled compiler at .build/crystal + gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 + TRACE + + Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run + stdout.to_s.should contain("gc:malloc events=1 duration=") + stderr.to_s.should contain("WARN: invalid trace 'Using compiled compiler at .build/crystal'") + end + end + + it "skips invalid traces when parsing stdin" do + stdin = IO::Memory.new <<-TRACE + Using compiled compiler at .build/crystal + gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 + TRACE + stdout = IO::Memory.new + stderr = IO::Memory.new + + Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run + stdout.to_s.should contain("gc:malloc events=1 duration=") + stderr.to_s.should be_empty + end +end diff --git a/src/compiler/crystal/command/trace.cr b/src/compiler/crystal/command/trace.cr index e1e637252d42..36760515ff23 100644 --- a/src/compiler/crystal/command/trace.cr +++ b/src/compiler/crystal/command/trace.cr @@ -35,7 +35,7 @@ class Crystal::Command case command when "stats" if input == "-" || File.exists?(input) - Tracing::StatsGenerator.new(input, color: color).run + Tracing::StatsCommand.new(input, color: color).run else error "file '#{input}' does not exist" end diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index 897e50aa86d6..2d075586fc8c 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -129,11 +129,20 @@ module Crystal end end - class StatsGenerator + class StatsCommand alias Action = Hash(String, Data) alias Section = Hash(String, Action) - def initialize(@path : String, @color : Bool) + @stdin : IO + @stdout : IO + @stderr : IO + + def initialize( + @path : String, + @color = false, + @stdin = STDIN, + @stdout = STDOUT, + @stderr = STDERR) end def run @@ -159,16 +168,16 @@ module Crystal stats.each do |section, actions| actions.each do |action, data| - Colorize.with.toggle(@color).yellow.surround(STDOUT) do - STDOUT << section << ':' << action + Colorize.with.toggle(@color).yellow.surround(@stdout) do + @stdout << section << ':' << action end data.each do |key, value| - STDOUT << ' ' << key << '=' - value.to_s(STDOUT) + @stdout << ' ' << key << '=' + value.to_s(@stdout) end - STDOUT << '\n' + @stdout << '\n' end end end @@ -181,7 +190,7 @@ module Crystal if line =~ PARSE_TRACE_RE yield $1, $2, $3, $4, $5 elsif @path != "-" - STDERR.print "WARN: invalid trace '#{line}'\n" + @stderr.print "WARN: invalid trace '#{line}'\n" end end end @@ -189,7 +198,7 @@ module Crystal private def open_trace_file(&) if @path == "-" - yield STDIN + yield @stdin else File.open(@path, "r") { |file| yield file } end From 18c9f799bca25a1ea48fe6575e84d70f3ad5118f Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Thu, 28 Dec 2023 14:09:45 +0100 Subject: [PATCH 05/20] Trace fixes + trace stats command optimizations Trace: - Fix measurements to use Time.monotonic - Fix printf escapes to represent unsigned integers Stats: - Calculate variance on-the-fly (rather than collecting each value) - Manual parse instead of regular expression (45% faster) - Avoid String allocations when possible (another 30% faster) - Add `--fast` option to skip the calculation min/max/mean/stddev (30% faster) --- src/compiler/crystal/command/trace.cr | 7 +- src/compiler/crystal/tools/tracing.cr | 223 +++++++++++++++++++++----- src/crystal/tracing.cr | 23 ++- src/gc/boehm.cr | 30 ++-- src/gc/none.cr | 6 +- 5 files changed, 228 insertions(+), 61 deletions(-) diff --git a/src/compiler/crystal/command/trace.cr b/src/compiler/crystal/command/trace.cr index 36760515ff23..26a6927e5a35 100644 --- a/src/compiler/crystal/command/trace.cr +++ b/src/compiler/crystal/command/trace.cr @@ -2,6 +2,7 @@ class Crystal::Command private def trace command = "stats" color = true + fast = false OptionParser.parse(@options) do |opts| opts.banner = <<-USAGE @@ -20,6 +21,10 @@ class Crystal::Command command = "stats" end + opts.on("--fast", "Skip min/max/mean/stddev details for faster processing") do + fast = true + end + opts.on("--no-color", "Disable colored output") do color = false end @@ -35,7 +40,7 @@ class Crystal::Command case command when "stats" if input == "-" || File.exists?(input) - Tracing::StatsCommand.new(input, color: color).run + Tracing::StatsCommand.new(input, fast: fast, color: color).run else error "file '#{input}' does not exist" end diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index 2d075586fc8c..94566e7e13ff 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -3,32 +3,34 @@ require "colorize" module Crystal module Tracing class Values(T) - delegate :size, :sum, :min, :max, to: @values + getter size : T = T.zero + getter sum : T = T.zero + getter min : T = T::MAX + getter max : T = T::MIN + @sum_square : T def initialize - @values = [] of T + @sum_square = T.zero end def <<(value) - @values << T.new(value) + v = T.new(value) + @size += 1 + @sum += v + @min = v if v < @min + @max = v if v > @max + @sum_square += v ** 2 end def average - if @values.empty? - T.new(0) - else - @values.sum / @values.size - end + size > 0 ? sum / size : T.zero end - def stddev(mean) - zero = T.new(0) - - if @values.empty? - zero + def stddev + if size > 0 + Math.sqrt((@sum_square / size) - (average ** 2)) else - variance = @values.reduce(zero) { |a, e| a + ((e - mean) ** 2) } / @values.size - Math.sqrt(variance) + T.zero end end @@ -44,9 +46,9 @@ module Crystal io << " max=" humanize io, max io << " mean=" - humanize io, mean = average + humanize io, average io << " ±" - humanize io, stddev(mean) + humanize io, stddev io << ']' end end @@ -95,17 +97,154 @@ module Crystal end end + module Parser + def self.parse_event(line : String) : Event? + reader = Char::Reader.new(line) + + section = parse_word + expect ' ' + + action = parse_word + expect ' ' + + t = parse_char('t', 'd') + expect '=' + time = parse_float + + Event.new(section, action, t, time, line) + end + + def self.parse_variable(line : String, name : String) : Float64? + if pos = line.index(name) + reader = Char::Reader.new(line, pos + name.bytesize + 1) + expect '=' + parse_float + end + end + + # Tries to parse known words, so we can return static strings instead of + # dynamically allocating the same string over an over, then falls back to + # allocate a string. + private macro parse_word + pos = reader.pos + case + {% for word in %w[ + gc + sched + malloc + realloc + collect:mark + collect:sweep + collect + heap_resize + spawn + enqueue + resume + reschedule + sleep + event_loop + mt:sleeping + mt:slept + ] %} + when parse_word?({{word}}) + {{word}} + {% end %} + else + loop do + %char = reader.current_char + return unless %char.ascii_letter? || {'-', '_', ':'}.includes?(%char) + break if reader.next_char == ' ' + end + reader.string[pos...reader.pos] + end + end + + private macro parse_word?(string) + %valid = true + {{string}}.each_char do |%char| + if reader.current_char == %char + reader.next_char + else + reader.pos = pos + %valid = false + break + end + end + %valid + end + + # Parses a float directly using a stack allocated buffer instead of + # allocating a dynamic string. + private macro parse_float + %buf = uninitialized UInt8[128] + %i = -1 + loop do + %char = reader.current_char + return unless %char.ascii_number? || %char == '.' + %buf[%i += 1] = %char.ord.to_u8! + break if reader.next_char == ' ' + end + %buf[%i] = 0_u8 + LibC.strtod(%buf, nil) + end + + private macro parse_t + %char = reader.current_char + if {'t', 'd'}.includes?(%char) + reader.next_char + %char + else + return + end + end + + private macro parse_char(*chars) + %char = reader.current_char + if {{chars}}.includes?(%char) + reader.next_char + %char + else + return + end + end + + private macro expect(char) + if reader.current_char == {{char}} + reader.next_char + else + return + end + end + end + + struct Event + getter section : String + getter action : String + getter t : Char + getter time : Float64 + getter line : String + + def initialize(@section, @action, @t, @time, @line) + end + + def variable(name : String) + Parser.parse_variable(line, name) + end + end + class Data - property events : Int64 + property events : UInt64 + property duration : Float64 getter values : Hash(Symbol, Values(Float64)) def initialize - @events = 0_i64 + @events = 0_u64 + @duration = 0_f64 @values = {} of Symbol => Values(Float64) end - def duration - @duration ||= Durations.new + def durations + @durations ||= Durations.new end def sizes @@ -115,8 +254,10 @@ module Crystal def each(&) yield :events, @events - if duration = @duration - yield :duration, duration + if durations = @durations + yield :durations, durations + elsif (duration = @duration) > 0 + yield :duration, duration.round(9) end if sizes = @sizes @@ -140,9 +281,11 @@ module Crystal def initialize( @path : String, @color = false, + @fast = false, @stdin = STDIN, @stdout = STDOUT, - @stderr = STDERR) + @stderr = STDERR + ) end def run @@ -152,15 +295,22 @@ module Crystal end end - each_event do |section, action, t, time, variables| - data = stats[section][action] + each_event do |event| + data = stats[event.section][event.action] data.events += 1 - data.duration << time.to_f if t == "d" - if section == "gc" - if action == "malloc" - if variables =~ /\bsize=(\d+)\s*/ - data.sizes << $1.to_i + if @fast + data.duration += event.time.to_f if event.t == 'd' + else + data.durations << event.time.to_f if event.t == 'd' + end + + next if @fast + + if event.section == "gc" + if event.action == "malloc" + if size = event.variable("size") + data.sizes << size.to_i end end end @@ -182,20 +332,21 @@ module Crystal end end - PARSE_TRACE_RE = /^(\w+) ([-_:\w]+) ([td])=(\d+\.\d+)\s*(.+)$/ - private def each_event(&) open_trace_file do |input| while line = input.gets(chomp: true) - if line =~ PARSE_TRACE_RE - yield $1, $2, $3, $4, $5 + if event = Parser.parse_event(line) + yield event elsif @path != "-" - @stderr.print "WARN: invalid trace '#{line}'\n" + @stderr.print "WARN: invalid trace '" + @stderr.print line + @stderr.print "'\n" end end end end + # TODO: support reading from gzip file private def open_trace_file(&) if @path == "-" yield @stdin diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index dc267cd859fc..ba35f2cccb2d 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -30,21 +30,20 @@ module Crystal macro trace(section, action, format = "", *args, &block) \{% if block %} - %start = ::Crystal::System::Time.monotonic + %start = ::Time.monotonic %ret = \{{yield}} - %stop = ::Crystal::System::Time.monotonic - %duration = { %stop[0] - %start[0], %stop[1] - %start[1] } - ::Crystal.trace_end('d', %duration, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + %stop = ::Time.monotonic + ::Crystal.trace_end('d', %stop - %start, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) %ret \{% else %} - %tick = ::Crystal::System::Time.monotonic + %tick = ::Time.monotonic ::Crystal.trace_end('t', %tick, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) nil \{% end %} end macro trace_end(t, tick_or_duration, section, action, format = "", *args) - %s, %ns = \{{tick_or_duration}} + # %s, %ns = \{{tick_or_duration}} # we may start to trace _before_ Thread.current and other objects have # been allocated, they're lazily allocated and since we trace GC.malloc we @@ -53,17 +52,17 @@ module Crystal if %thread = Thread.current? if %scheduler = %thread.scheduler? %fiber = %scheduler.@current - ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%d.%09d thread=%lx fiber=%lx [%s] \{{format.id}}\n", - %s, %ns, %thread, %fiber.object_id, %fiber.name || "", \{{args.splat}}) + ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx fiber=%lx [%s] \{{format.id}}\n", + (\{{tick_or_duration}}).to_f, %thread, %fiber.object_id, %fiber.name || "", \{{args.splat}}) else # fallback: no scheduler (or not started yet?) for the current thread - ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%d.%09d thread=%lx \{{format.id}}\n", - %s, %ns, %thread, \{{args.splat}}) + ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", + (\{{tick_or_duration}}).to_f, %thread, \{{args.splat}}) end else # fallback: no Thread object (yet) - ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%d.%09d thread=%lx \{{format.id}}\n", - %s, %ns, Crystal::System::Thread.current_handle, \{{args.splat}}) + ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", + (\{{tick_or_duration}}).to_f, Crystal::System::Thread.current_handle, \{{args.splat}}) end end {% else %} diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr index 72709ecbc607..f3ecf7432a10 100644 --- a/src/gc/boehm.cr +++ b/src/gc/boehm.cr @@ -170,21 +170,21 @@ module GC # :nodoc: def self.malloc(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%ld", size do + Crystal.trace "gc", "malloc", "size=%lu", size do LibGC.malloc(size) end end # :nodoc: def self.malloc_atomic(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%ld atomic=1", size do + Crystal.trace "gc", "malloc", "size=%lu atomic=1", size do LibGC.malloc_atomic(size) end end # :nodoc: def self.realloc(ptr : Void*, size : LibC::SizeT) : Void* - Crystal.trace "gc", "realloc", "size=%ld", size do + Crystal.trace "gc", "realloc", "size=%lu", size do LibGC.realloc(ptr, size) end end @@ -221,14 +221,16 @@ module GC {% if flag?(:tracing) %} @@on_heap_resize : LibGC::OnHeapResizeProc? @@on_collection_event : LibGC::OnCollectionEventProc? - @@collect_start_s = 0_i64 - @@collect_start_ns = 0_i32 + + @@collect_start = uninitialized Time::Span + @@mark_start = uninitialized Time::Span + @@sweep_start = uninitialized Time::Span 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=%lld", UInt64.new(new_size) + Crystal.trace "gc", "heap_resize", "size=%llu", UInt64.new(new_size) @@on_heap_resize.try(&.call(new_size)) }) end @@ -238,13 +240,23 @@ module GC LibGC.set_on_collection_event(->(event_type : LibGC::EventType) { # Crystal.trace "gc", "on_collection_event", "type=%s", event_type.to_s + case event_type when .start? - @@collect_start_s, @@collect_start_ns = Crystal::System::Time.monotonic + @@collect_start = Time.monotonic + when .mark_start? + @@mark_start = Time.monotonic + when .reclaim_start? + @@sweep_start = Time.monotonic when .end? - end_s, end_ns = Crystal::System::Time.monotonic - duration = {end_s - @@collect_start_s, end_ns - @@collect_start_ns} + duration = ::Time.monotonic - @@collect_start Crystal.trace_end 'd', duration, "gc", "collect" + when .mark_end? + duration = ::Time.monotonic - @@mark_start + Crystal.trace_end 'd', duration, "gc", "collect:mark" + when .reclaim_end? + duration = ::Time.monotonic - @@sweep_start + Crystal.trace_end 'd', duration, "gc", "collect:sweep" end @@on_collection_event.try(&.call(event_type)) }) diff --git a/src/gc/none.cr b/src/gc/none.cr index 20a2cd9a738b..89de335b9caa 100644 --- a/src/gc/none.cr +++ b/src/gc/none.cr @@ -10,19 +10,19 @@ module GC # :nodoc: def self.malloc(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%ld", size + Crystal.trace "gc", "malloc", "size=%lu", size LibC.malloc(size) end # :nodoc: def self.malloc_atomic(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%ld atomic=1", size + Crystal.trace "gc", "malloc", "size=%lu atomic=1", size LibC.malloc(size) end # :nodoc: def self.realloc(pointer : Void*, size : LibC::SizeT) : Void* - Crystal.trace "gc", "realloc", "size=%ld", size + Crystal.trace "gc", "realloc", "size=%lu", size LibC.realloc(pointer, size) end From 61ab769d9d4b2662bb6b34df900d61d4c14c66e4 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Thu, 28 Dec 2023 23:08:58 +0100 Subject: [PATCH 06/20] Add CRYSTAL_DEBUG envvar to selectively trace The actual trace logs are disabled by default and you must declare the `CRYSTAL_DEBUG` to enable each section (`gc`, `sched`). For example: ``` $ crystal build app.cr $ CRYSTAL_DEBUG=gc,sched ./app 2> >(gzip > trace.log.gz) $ zcat trace.log.gz | crystal tool trace - ``` --- spec/compiler/crystal/tools/tracing_spec.cr | 32 ++++- src/compiler/crystal/tools/tracing.cr | 1 - src/crystal/main.cr | 1 + src/crystal/tracing.cr | 129 +++++++++++++------- src/gc/boehm.cr | 6 +- src/lib_c/aarch64-android/c/string.cr | 1 + src/lib_c/aarch64-darwin/c/string.cr | 1 + src/lib_c/aarch64-linux-gnu/c/string.cr | 1 + src/lib_c/aarch64-linux-musl/c/string.cr | 1 + src/lib_c/arm-linux-gnueabihf/c/string.cr | 1 + src/lib_c/i386-linux-gnu/c/string.cr | 1 + src/lib_c/i386-linux-musl/c/string.cr | 1 + src/lib_c/wasm32-wasi/c/string.cr | 1 + src/lib_c/x86_64-darwin/c/string.cr | 1 + src/lib_c/x86_64-dragonfly/c/string.cr | 1 + src/lib_c/x86_64-freebsd/c/string.cr | 1 + src/lib_c/x86_64-linux-gnu/c/string.cr | 1 + src/lib_c/x86_64-linux-musl/c/string.cr | 1 + src/lib_c/x86_64-netbsd/c/string.cr | 1 + src/lib_c/x86_64-openbsd/c/string.cr | 1 + src/lib_c/x86_64-windows-msvc/c/string.cr | 1 + 21 files changed, 134 insertions(+), 51 deletions(-) diff --git a/spec/compiler/crystal/tools/tracing_spec.cr b/spec/compiler/crystal/tools/tracing_spec.cr index a43091072325..55f338cc4a7c 100644 --- a/spec/compiler/crystal/tools/tracing_spec.cr +++ b/spec/compiler/crystal/tools/tracing_spec.cr @@ -19,6 +19,30 @@ describe Crystal::Tracing::StatsCommand do Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run output = stdout.to_s + output.should contain("gc:malloc events=4 durations=") + output.should contain("gc:collect events=1 durations=") + output.should contain("gc:heap_resize events=1") + output.should contain("sched:spawn events=1") + output.should contain("sched:enqueue events=1 durations=") + stderr.to_s.should be_empty + end + + it "--fast" do + stdin = IO::Memory.new <<-TRACE + gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 + gc malloc d=0.000009074 thread=7f0ea62bd740 size=4 atomic=1 + gc malloc d=0.000000128 thread=7f0ea62bd740 size=144 + sched spawn t=102125.792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 + sched enqueue d=0.000101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 + gc malloc d=0.000000222 thread=7f0ea62bd740 size=24 + gc collect d=0.000079489 thread=7f0ea62bd740 + gc heap_resize t=102125.791993928 thread=7f0ea62bd740 size=131072 + TRACE + stdout = IO::Memory.new + stderr = IO::Memory.new + + Crystal::Tracing::StatsCommand.new("-", fast: true, stdin: stdin, stdout: stdout, stderr: stderr).run + output = stdout.to_s output.should contain("gc:malloc events=4 duration=") output.should contain("gc:collect events=1 duration=") output.should contain("gc:heap_resize events=1") @@ -42,8 +66,8 @@ describe Crystal::Tracing::StatsCommand do Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run output = stdout.to_s - output.should contain("gc:malloc events=3 duration=") - output.should contain("gc:collect events=1 duration=") + output.should contain("gc:malloc events=3 durations=") + output.should contain("gc:collect events=1 durations=") stderr.to_s.should be_empty end end @@ -60,7 +84,7 @@ describe Crystal::Tracing::StatsCommand do TRACE Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run - stdout.to_s.should contain("gc:malloc events=1 duration=") + stdout.to_s.should contain("gc:malloc events=1 durations=") stderr.to_s.should contain("WARN: invalid trace 'Using compiled compiler at .build/crystal'") end end @@ -74,7 +98,7 @@ describe Crystal::Tracing::StatsCommand do stderr = IO::Memory.new Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run - stdout.to_s.should contain("gc:malloc events=1 duration=") + stdout.to_s.should contain("gc:malloc events=1 durations=") stderr.to_s.should be_empty end end diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index 94566e7e13ff..5918591cbce7 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -346,7 +346,6 @@ module Crystal end end - # TODO: support reading from gzip file private def open_trace_file(&) if @path == "-" yield @stdin diff --git a/src/crystal/main.cr b/src/crystal/main.cr index 480571d06fb4..50ab5d01fbb4 100644 --- a/src/crystal/main.cr +++ b/src/crystal/main.cr @@ -46,6 +46,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/tracing.cr b/src/crystal/tracing.cr index ba35f2cccb2d..81fecf4f6c22 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -1,50 +1,85 @@ module Crystal {% if flag?(:tracing) %} - # Formats and prints a log message to STDERR. The generated message is - # limited to 511 bytes after which it will be truncated. - # - # Doesn't use `dprintf(2)` that may do multiple writes to fd, leading to - # smashed log lines with multithreading, we prefer to use `snprintf(2)` with - # a stack allocated buffer that has a maximum size of PIPE_BUF bytes minus - # one byte for the terminating null byte. - # - # Eventually writes to STDERR in a single write operation that should be - # atomic since the buffer is smaller than of equal to PIPE_BUF, on POSIX - # platforms at least. - # - # Doesn't continue to write on partial writes (e.g. interrupted by a signal) - # as the output could be smashed with a parallel write. - def self.trace_log(format : String, *args) : Nil - buffer = uninitialized UInt8[512] + module Tracing + @@gc = false + @@sched = false - len = LibC.snprintf(buffer, buffer.size, format, *args) - return if len == 0 + def self.init + debug = Pointer(UInt8).null - {% if flag?(:win32) %} - # FIXME: atomicity of _write on win32? - LibC._write(2, buffer, len) - {% else %} - LibC.write(2, buffer, len) - {% end %} + {% if flag?(:win32) %} + buf = uninitialized UInt8[256] + len = LibC.GetEnvironmentVariableW("CRYSTAL_DEBUG", buf, buf.size) + debug = buf.to_unsafe + {% else %} + debug = LibC.getenv("CRYSTAL_DEBUG") + {% end %} + + if debug + @@gc = !LibC.strstr(debug, "gc").null? + @@sched = !LibC.strstr(debug, "sched").null? + end + end + + def self.enabled?(section : String) : Bool + case section + when "gc" + @@gc + when "sched" + @@sched + else + false + end + end + + # Formats and prints a log message to STDERR. The generated message is + # limited to 511 bytes after which it will be truncated. + # + # Doesn't use `dprintf(2)` that may do multiple writes to fd, leading to + # smashed log lines with multithreading, we prefer to use `snprintf(2)` with + # a stack allocated buffer that has a maximum size of PIPE_BUF bytes minus + # one byte for the terminating null byte. + # + # Eventually writes to STDERR in a single write operation that should be + # atomic since the buffer is smaller than of equal to PIPE_BUF, on POSIX + # platforms at least. + # + # Doesn't continue to write on partial writes (e.g. interrupted by a signal) + # as the output could be smashed with a parallel write. + def self.log(format : String, *args) : Nil + buffer = uninitialized UInt8[512] + + len = LibC.snprintf(buffer, buffer.size, format, *args) + return if len == 0 + + {% if flag?(:win32) %} + # FIXME: atomicity of _write on win32? + LibC._write(2, buffer, len) + {% else %} + LibC.write(2, buffer, len) + {% end %} + end end macro trace(section, action, format = "", *args, &block) - \{% if block %} - %start = ::Time.monotonic - %ret = \{{yield}} - %stop = ::Time.monotonic - ::Crystal.trace_end('d', %stop - %start, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) - %ret - \{% else %} - %tick = ::Time.monotonic - ::Crystal.trace_end('t', %tick, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) - nil - \{% end %} + if ::Crystal::Tracing.enabled?(\{{section}}) + \{% if block %} + %start = ::Time.monotonic + %ret = \{{yield}} + %stop = ::Time.monotonic + ::Crystal.trace_end('d', %stop - %start, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + %ret + \{% else %} + %tick = ::Time.monotonic + ::Crystal.trace_end('t', %tick, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + nil + \{% end %} + else + \{{yield}} + end end macro trace_end(t, tick_or_duration, section, action, format = "", *args) - # %s, %ns = \{{tick_or_duration}} - # we may 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 are allocate (otherwise we hit infinite @@ -52,21 +87,27 @@ module Crystal if %thread = Thread.current? if %scheduler = %thread.scheduler? %fiber = %scheduler.@current - ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx fiber=%lx [%s] \{{format.id}}\n", - (\{{tick_or_duration}}).to_f, %thread, %fiber.object_id, %fiber.name || "", \{{args.splat}}) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx fiber=%lx [%s] \{{format.id}}\n", + (\{{tick_or_duration}}).to_f, %thread, %fiber.object_id, %fiber.name || "", \{{args.splat}}) else # fallback: no scheduler (or not started yet?) for the current thread - ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", - (\{{tick_or_duration}}).to_f, %thread, \{{args.splat}}) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", + (\{{tick_or_duration}}).to_f, %thread, \{{args.splat}}) end else # fallback: no Thread object (yet) - ::Crystal.trace_log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", - (\{{tick_or_duration}}).to_f, Crystal::System::Thread.current_handle, \{{args.splat}}) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", + (\{{tick_or_duration}}).to_f, Crystal::System::Thread.current_handle, \{{args.splat}}) end end {% else %} - def self.trace_log(format : String, *args) + module Tracing + def self.enabled?(section) + false + end + + def self.log(format : String, *args) + end end macro trace(section, action, format = "", *args, &block) diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr index f3ecf7432a10..7330235a9107 100644 --- a/src/gc/boehm.cr +++ b/src/gc/boehm.cr @@ -202,8 +202,10 @@ module GC end {% if flag?(:tracing) %} - set_on_heap_resize_proc - set_on_collection_events_proc + 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 diff --git a/src/lib_c/aarch64-android/c/string.cr b/src/lib_c/aarch64-android/c/string.cr index 5133435e13dc..bbf1240f92de 100644 --- a/src/lib_c/aarch64-android/c/string.cr +++ b/src/lib_c/aarch64-android/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(__lhs : Char*, __rhs : Char*) : Int fun strerror(__errno_value : Int) : Char* fun strlen(__s : Char*) : SizeT + fun strstr(Char*, Char*) : Char* end diff --git a/src/lib_c/aarch64-darwin/c/string.cr b/src/lib_c/aarch64-darwin/c/string.cr index 02e025ae4880..57075b1bfba4 100644 --- a/src/lib_c/aarch64-darwin/c/string.cr +++ b/src/lib_c/aarch64-darwin/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/aarch64-linux-gnu/c/string.cr b/src/lib_c/aarch64-linux-gnu/c/string.cr index c583804acd98..3131c15f52bf 100644 --- a/src/lib_c/aarch64-linux-gnu/c/string.cr +++ b/src/lib_c/aarch64-linux-gnu/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT + fun strstr(s1 : Char*, s2 : Char*) : Char* end diff --git a/src/lib_c/aarch64-linux-musl/c/string.cr b/src/lib_c/aarch64-linux-musl/c/string.cr index 02e025ae4880..57075b1bfba4 100644 --- a/src/lib_c/aarch64-linux-musl/c/string.cr +++ b/src/lib_c/aarch64-linux-musl/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/arm-linux-gnueabihf/c/string.cr b/src/lib_c/arm-linux-gnueabihf/c/string.cr index c583804acd98..3131c15f52bf 100644 --- a/src/lib_c/arm-linux-gnueabihf/c/string.cr +++ b/src/lib_c/arm-linux-gnueabihf/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT + fun strstr(s1 : Char*, s2 : Char*) : Char* end diff --git a/src/lib_c/i386-linux-gnu/c/string.cr b/src/lib_c/i386-linux-gnu/c/string.cr index c583804acd98..6e76789ae04e 100644 --- a/src/lib_c/i386-linux-gnu/c/string.cr +++ b/src/lib_c/i386-linux-gnu/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/i386-linux-musl/c/string.cr b/src/lib_c/i386-linux-musl/c/string.cr index 02e025ae4880..57075b1bfba4 100644 --- a/src/lib_c/i386-linux-musl/c/string.cr +++ b/src/lib_c/i386-linux-musl/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/wasm32-wasi/c/string.cr b/src/lib_c/wasm32-wasi/c/string.cr index 5be77e03cf1c..ac3795500a2e 100644 --- a/src/lib_c/wasm32-wasi/c/string.cr +++ b/src/lib_c/wasm32-wasi/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : ULong + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-darwin/c/string.cr b/src/lib_c/x86_64-darwin/c/string.cr index 02e025ae4880..57075b1bfba4 100644 --- a/src/lib_c/x86_64-darwin/c/string.cr +++ b/src/lib_c/x86_64-darwin/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-dragonfly/c/string.cr b/src/lib_c/x86_64-dragonfly/c/string.cr index 02e025ae4880..57075b1bfba4 100644 --- a/src/lib_c/x86_64-dragonfly/c/string.cr +++ b/src/lib_c/x86_64-dragonfly/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-freebsd/c/string.cr b/src/lib_c/x86_64-freebsd/c/string.cr index 02e025ae4880..57075b1bfba4 100644 --- a/src/lib_c/x86_64-freebsd/c/string.cr +++ b/src/lib_c/x86_64-freebsd/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-linux-gnu/c/string.cr b/src/lib_c/x86_64-linux-gnu/c/string.cr index c583804acd98..3131c15f52bf 100644 --- a/src/lib_c/x86_64-linux-gnu/c/string.cr +++ b/src/lib_c/x86_64-linux-gnu/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT + fun strstr(s1 : Char*, s2 : Char*) : Char* end diff --git a/src/lib_c/x86_64-linux-musl/c/string.cr b/src/lib_c/x86_64-linux-musl/c/string.cr index 02e025ae4880..57075b1bfba4 100644 --- a/src/lib_c/x86_64-linux-musl/c/string.cr +++ b/src/lib_c/x86_64-linux-musl/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-netbsd/c/string.cr b/src/lib_c/x86_64-netbsd/c/string.cr index 471d1ed82b36..fdd6d96a7da3 100644 --- a/src/lib_c/x86_64-netbsd/c/string.cr +++ b/src/lib_c/x86_64-netbsd/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : ULong + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-openbsd/c/string.cr b/src/lib_c/x86_64-openbsd/c/string.cr index 471d1ed82b36..fdd6d96a7da3 100644 --- a/src/lib_c/x86_64-openbsd/c/string.cr +++ b/src/lib_c/x86_64-openbsd/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : ULong + fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-windows-msvc/c/string.cr b/src/lib_c/x86_64-windows-msvc/c/string.cr index c583804acd98..3131c15f52bf 100644 --- a/src/lib_c/x86_64-windows-msvc/c/string.cr +++ b/src/lib_c/x86_64-windows-msvc/c/string.cr @@ -6,4 +6,5 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT + fun strstr(s1 : Char*, s2 : Char*) : Char* end From 43767ef6e07e6bed349fe5be8489e5be83ca93e0 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 29 Dec 2023 14:11:02 +0100 Subject: [PATCH 07/20] Tokenize CRYSTAL_DEBUG variable So we match exact references to 'gc' and 'sched' and expect the delimiter to be a comma (','). This allows to remove the `strstr(3)` libc call that was previously introduced and the tokenization and comparison now relies on slices and pure crystal (no need to bring `strsep(3)` or `strtok(3)` libc calls). --- src/crystal/tracing.cr | 34 +++++++++++++++-------- src/lib_c/aarch64-android/c/string.cr | 1 - src/lib_c/aarch64-darwin/c/string.cr | 1 - src/lib_c/aarch64-linux-gnu/c/string.cr | 1 - src/lib_c/aarch64-linux-musl/c/string.cr | 1 - src/lib_c/arm-linux-gnueabihf/c/string.cr | 1 - src/lib_c/i386-linux-gnu/c/string.cr | 1 - src/lib_c/i386-linux-musl/c/string.cr | 1 - src/lib_c/wasm32-wasi/c/string.cr | 1 - src/lib_c/x86_64-darwin/c/string.cr | 1 - src/lib_c/x86_64-dragonfly/c/string.cr | 1 - src/lib_c/x86_64-freebsd/c/string.cr | 1 - src/lib_c/x86_64-linux-gnu/c/string.cr | 1 - src/lib_c/x86_64-linux-musl/c/string.cr | 1 - src/lib_c/x86_64-netbsd/c/string.cr | 1 - src/lib_c/x86_64-openbsd/c/string.cr | 1 - src/lib_c/x86_64-windows-msvc/c/string.cr | 1 - 17 files changed, 23 insertions(+), 27 deletions(-) diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index 81fecf4f6c22..9625c0fde9c2 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -1,37 +1,49 @@ module Crystal {% if flag?(:tracing) %} + # :nodoc: module Tracing - @@gc = false - @@sched = false - def self.init - debug = Pointer(UInt8).null + @@gc = false + @@sched = false {% if flag?(:win32) %} buf = uninitialized UInt8[256] len = LibC.GetEnvironmentVariableW("CRYSTAL_DEBUG", buf, buf.size) - debug = buf.to_unsafe + debug = buf.to_slice(len) if len > 0 {% else %} - debug = LibC.getenv("CRYSTAL_DEBUG") + if ptr = LibC.getenv("CRYSTAL_DEBUG") + len = LibC.strlen(ptr) + debug = Slice.new(ptr, len) if len > 0 + end {% end %} - if debug - @@gc = !LibC.strstr(debug, "gc").null? - @@sched = !LibC.strstr(debug, "sched").null? + return unless debug + + each_token(debug) do |token| + @@gc = true if token == "gc".to_slice + @@sched = true if token == "sched".to_slice end end def self.enabled?(section : String) : Bool case section when "gc" - @@gc + !!@@gc when "sched" - @@sched + !!@@sched else false 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 + # Formats and prints a log message to STDERR. The generated message is # limited to 511 bytes after which it will be truncated. # diff --git a/src/lib_c/aarch64-android/c/string.cr b/src/lib_c/aarch64-android/c/string.cr index bbf1240f92de..5133435e13dc 100644 --- a/src/lib_c/aarch64-android/c/string.cr +++ b/src/lib_c/aarch64-android/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(__lhs : Char*, __rhs : Char*) : Int fun strerror(__errno_value : Int) : Char* fun strlen(__s : Char*) : SizeT - fun strstr(Char*, Char*) : Char* end diff --git a/src/lib_c/aarch64-darwin/c/string.cr b/src/lib_c/aarch64-darwin/c/string.cr index 57075b1bfba4..02e025ae4880 100644 --- a/src/lib_c/aarch64-darwin/c/string.cr +++ b/src/lib_c/aarch64-darwin/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/aarch64-linux-gnu/c/string.cr b/src/lib_c/aarch64-linux-gnu/c/string.cr index 3131c15f52bf..c583804acd98 100644 --- a/src/lib_c/aarch64-linux-gnu/c/string.cr +++ b/src/lib_c/aarch64-linux-gnu/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT - fun strstr(s1 : Char*, s2 : Char*) : Char* end diff --git a/src/lib_c/aarch64-linux-musl/c/string.cr b/src/lib_c/aarch64-linux-musl/c/string.cr index 57075b1bfba4..02e025ae4880 100644 --- a/src/lib_c/aarch64-linux-musl/c/string.cr +++ b/src/lib_c/aarch64-linux-musl/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/arm-linux-gnueabihf/c/string.cr b/src/lib_c/arm-linux-gnueabihf/c/string.cr index 3131c15f52bf..c583804acd98 100644 --- a/src/lib_c/arm-linux-gnueabihf/c/string.cr +++ b/src/lib_c/arm-linux-gnueabihf/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT - fun strstr(s1 : Char*, s2 : Char*) : Char* end diff --git a/src/lib_c/i386-linux-gnu/c/string.cr b/src/lib_c/i386-linux-gnu/c/string.cr index 6e76789ae04e..c583804acd98 100644 --- a/src/lib_c/i386-linux-gnu/c/string.cr +++ b/src/lib_c/i386-linux-gnu/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/i386-linux-musl/c/string.cr b/src/lib_c/i386-linux-musl/c/string.cr index 57075b1bfba4..02e025ae4880 100644 --- a/src/lib_c/i386-linux-musl/c/string.cr +++ b/src/lib_c/i386-linux-musl/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/wasm32-wasi/c/string.cr b/src/lib_c/wasm32-wasi/c/string.cr index ac3795500a2e..5be77e03cf1c 100644 --- a/src/lib_c/wasm32-wasi/c/string.cr +++ b/src/lib_c/wasm32-wasi/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : ULong - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-darwin/c/string.cr b/src/lib_c/x86_64-darwin/c/string.cr index 57075b1bfba4..02e025ae4880 100644 --- a/src/lib_c/x86_64-darwin/c/string.cr +++ b/src/lib_c/x86_64-darwin/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-dragonfly/c/string.cr b/src/lib_c/x86_64-dragonfly/c/string.cr index 57075b1bfba4..02e025ae4880 100644 --- a/src/lib_c/x86_64-dragonfly/c/string.cr +++ b/src/lib_c/x86_64-dragonfly/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-freebsd/c/string.cr b/src/lib_c/x86_64-freebsd/c/string.cr index 57075b1bfba4..02e025ae4880 100644 --- a/src/lib_c/x86_64-freebsd/c/string.cr +++ b/src/lib_c/x86_64-freebsd/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-linux-gnu/c/string.cr b/src/lib_c/x86_64-linux-gnu/c/string.cr index 3131c15f52bf..c583804acd98 100644 --- a/src/lib_c/x86_64-linux-gnu/c/string.cr +++ b/src/lib_c/x86_64-linux-gnu/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT - fun strstr(s1 : Char*, s2 : Char*) : Char* end diff --git a/src/lib_c/x86_64-linux-musl/c/string.cr b/src/lib_c/x86_64-linux-musl/c/string.cr index 57075b1bfba4..02e025ae4880 100644 --- a/src/lib_c/x86_64-linux-musl/c/string.cr +++ b/src/lib_c/x86_64-linux-musl/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : SizeT - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-netbsd/c/string.cr b/src/lib_c/x86_64-netbsd/c/string.cr index fdd6d96a7da3..471d1ed82b36 100644 --- a/src/lib_c/x86_64-netbsd/c/string.cr +++ b/src/lib_c/x86_64-netbsd/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : ULong - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-openbsd/c/string.cr b/src/lib_c/x86_64-openbsd/c/string.cr index fdd6d96a7da3..471d1ed82b36 100644 --- a/src/lib_c/x86_64-openbsd/c/string.cr +++ b/src/lib_c/x86_64-openbsd/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(x0 : Char*, x1 : Char*) : Int fun strerror(x0 : Int) : Char* fun strlen(x0 : Char*) : ULong - fun strstr(x0 : Char*, x1 : Char*) : Char* end diff --git a/src/lib_c/x86_64-windows-msvc/c/string.cr b/src/lib_c/x86_64-windows-msvc/c/string.cr index 3131c15f52bf..c583804acd98 100644 --- a/src/lib_c/x86_64-windows-msvc/c/string.cr +++ b/src/lib_c/x86_64-windows-msvc/c/string.cr @@ -6,5 +6,4 @@ lib LibC fun strcmp(s1 : Char*, s2 : Char*) : Int fun strerror(errnum : Int) : Char* fun strlen(s : Char*) : SizeT - fun strstr(s1 : Char*, s2 : Char*) : Char* end From 4a6ba89915e63d2cd4c6a4636d67a66ea02a842f Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Mon, 15 Jan 2024 17:48:25 +0100 Subject: [PATCH 08/20] Rename CRYSTAL_DEBUG to CRYSTAL_TRACE + some documentation tweaks --- src/compiler/crystal/tools/tracing.cr | 42 +++++++++++++++------------ src/crystal/tracing.cr | 20 +++++++++---- 2 files changed, 38 insertions(+), 24 deletions(-) diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index 5918591cbce7..d3bd9dc946a3 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -2,6 +2,29 @@ require "colorize" module Crystal module Tracing + # List of known words used by trace calls, so we can return static strings + # instead of dynamically allocating the same few strings over an over. This + # dramatically improves performance when parsing large traces. + WORDS_DICTIONNARY = %w[ + gc + malloc + realloc + collect:mark + collect:sweep + collect + + sched + heap_resize + spawn + enqueue + resume + reschedule + sleep + event_loop + mt:sleeping + mt:slept + ] + class Values(T) getter size : T = T.zero getter sum : T = T.zero @@ -128,24 +151,7 @@ module Crystal private macro parse_word pos = reader.pos case - {% for word in %w[ - gc - sched - malloc - realloc - collect:mark - collect:sweep - collect - heap_resize - spawn - enqueue - resume - reschedule - sleep - event_loop - mt:sleeping - mt:slept - ] %} + {% for word in WORDS_DICTIONNARY %} when parse_word?({{word}}) {{word}} {% end %} diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index 9625c0fde9c2..3849192def6b 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -2,16 +2,22 @@ module Crystal {% if flag?(:tracing) %} # :nodoc: module Tracing + # Setups tracing, parsing the CRYSTAL_TRACE environment variable to enable + # the sections to trace (`gc` and/or `sched`). + # + # 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. def self.init @@gc = false @@sched = false {% if flag?(:win32) %} buf = uninitialized UInt8[256] - len = LibC.GetEnvironmentVariableW("CRYSTAL_DEBUG", buf, buf.size) + len = LibC.GetEnvironmentVariableW("CRYSTAL_TRACE", buf, buf.size) debug = buf.to_slice(len) if len > 0 {% else %} - if ptr = LibC.getenv("CRYSTAL_DEBUG") + if ptr = LibC.getenv("CRYSTAL_TRACE") len = LibC.strlen(ptr) debug = Slice.new(ptr, len) if len > 0 end @@ -50,11 +56,13 @@ module Crystal # Doesn't use `dprintf(2)` that may do multiple writes to fd, leading to # smashed log lines with multithreading, we prefer to use `snprintf(2)` with # a stack allocated buffer that has a maximum size of PIPE_BUF bytes minus - # one byte for the terminating null byte. + # one byte for the terminating null byte (targets such as linux have a + # pipe buf of 4096 but I chose a conservative number that should be large + # enough). # - # Eventually writes to STDERR in a single write operation that should be - # atomic since the buffer is smaller than of equal to PIPE_BUF, on POSIX - # platforms at least. + # Eventually writes to STDERR in a single write operation, this should be + # atomic since the buffer is smaller than of equal to PIPE_BUF (on POSIX + # platforms at least). # # Doesn't continue to write on partial writes (e.g. interrupted by a signal) # as the output could be smashed with a parallel write. From 7a828ff1a0df56caf265f1f173c1bdb5bad856e9 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Tue, 14 May 2024 13:48:38 +0200 Subject: [PATCH 09/20] Leverage Crystal::System.print_error + StringPool Renames `print_error(fmt, *args, &)` as `printf(fmt, *args, &)` as it involves formatting a string, not printing the formatted string to the standard error. Also introduces `print_error(bytes)` to do the actual print to standard error (without formatting) so we can do both format then print to error in two steps. Since crystal printf is a subset of C printf and we don't support printing floats, the trace is changed to print durations as nanoseconds integer + fix the tick to be the monotonic time since the program started instead of the current monotonic time (should be more useful). Last but not least, fixes the 'crystal tool trace stats' command to parse an integer instead of float (removes dependency on `strtod(2)`) and to leverage StringPool instead of the fixed list of static strings, so adding or removing sections/actions won't affect the command. --- spec/compiler/crystal/tools/tracing_spec.cr | 44 +++--- spec/std/crystal/system_spec.cr | 24 ++-- src/compiler/crystal/tools/tracing.cr | 95 +++++-------- src/concurrent.cr | 2 +- src/crystal/scheduler.cr | 6 +- src/crystal/system/print_error.cr | 25 ++-- src/crystal/tracing.cr | 145 ++++++++++++++------ 7 files changed, 182 insertions(+), 159 deletions(-) diff --git a/spec/compiler/crystal/tools/tracing_spec.cr b/spec/compiler/crystal/tools/tracing_spec.cr index 55f338cc4a7c..b146248fbaa3 100644 --- a/spec/compiler/crystal/tools/tracing_spec.cr +++ b/spec/compiler/crystal/tools/tracing_spec.cr @@ -5,14 +5,14 @@ require "../../../support/tempfile" describe Crystal::Tracing::StatsCommand do it "parses stdin" do stdin = IO::Memory.new <<-TRACE - gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 - gc malloc d=0.000009074 thread=7f0ea62bd740 size=4 atomic=1 - gc malloc d=0.000000128 thread=7f0ea62bd740 size=144 - sched spawn t=102125.792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 - sched enqueue d=0.000101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 - gc malloc d=0.000000222 thread=7f0ea62bd740 size=24 - gc collect d=0.000079489 thread=7f0ea62bd740 - gc heap_resize t=102125.791993928 thread=7f0ea62bd740 size=131072 + gc malloc d=23724 thread=7f0ea62bd740 size=16 + gc malloc d=9074 thread=7f0ea62bd740 size=4 atomic=1 + gc malloc d=128 thread=7f0ea62bd740 size=144 + sched spawn t=102125792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 + sched enqueue d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 + gc malloc d=222 thread=7f0ea62bd740 size=24 + gc collect d=79489 thread=7f0ea62bd740 + gc heap_resize t=102125791993928 thread=7f0ea62bd740 size=131072 TRACE stdout = IO::Memory.new stderr = IO::Memory.new @@ -29,14 +29,14 @@ describe Crystal::Tracing::StatsCommand do it "--fast" do stdin = IO::Memory.new <<-TRACE - gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 - gc malloc d=0.000009074 thread=7f0ea62bd740 size=4 atomic=1 - gc malloc d=0.000000128 thread=7f0ea62bd740 size=144 - sched spawn t=102125.792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 - sched enqueue d=0.000101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 - gc malloc d=0.000000222 thread=7f0ea62bd740 size=24 - gc collect d=0.000079489 thread=7f0ea62bd740 - gc heap_resize t=102125.791993928 thread=7f0ea62bd740 size=131072 + gc malloc d=23724 thread=7f0ea62bd740 size=16 + gc malloc d=9074 thread=7f0ea62bd740 size=4 atomic=1 + gc malloc d=128 thread=7f0ea62bd740 size=144 + sched spawn t=102125792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 + sched enqueue d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 + gc malloc d=222 thread=7f0ea62bd740 size=24 + gc collect d=79489 thread=7f0ea62bd740 + gc heap_resize t=102125791993928 thread=7f0ea62bd740 size=131072 TRACE stdout = IO::Memory.new stderr = IO::Memory.new @@ -58,10 +58,10 @@ describe Crystal::Tracing::StatsCommand do with_tempfile("trace.log") do |path| File.write path, <<-TRACE - gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 - gc malloc d=0.000009074 thread=7f0ea62bd740 size=4 atomic=1 - gc malloc d=0.000000222 thread=7f0ea62bd740 size=24 - gc collect d=0.000079489 thread=7f0ea62bd740 + gc malloc d=23724 thread=7f0ea62bd740 size=16 + gc malloc d=9074 thread=7f0ea62bd740 size=4 atomic=1 + gc malloc d=222 thread=7f0ea62bd740 size=24 + gc collect d=79489 thread=7f0ea62bd740 TRACE Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run @@ -80,7 +80,7 @@ describe Crystal::Tracing::StatsCommand do with_tempfile("trace.log") do |path| File.write path, <<-TRACE Using compiled compiler at .build/crystal - gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 + gc malloc d=23724 thread=7f0ea62bd740 size=16 TRACE Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run @@ -92,7 +92,7 @@ describe Crystal::Tracing::StatsCommand do it "skips invalid traces when parsing stdin" do stdin = IO::Memory.new <<-TRACE Using compiled compiler at .build/crystal - gc malloc d=0.000023724 thread=7f0ea62bd740 size=16 + gc malloc d=23724 thread=7f0ea62bd740 size=16 TRACE stdout = IO::Memory.new stderr = IO::Memory.new diff --git a/spec/std/crystal/system_spec.cr b/spec/std/crystal/system_spec.cr index 8e710f860a53..29e24438ed28 100644 --- a/spec/std/crystal/system_spec.cr +++ b/spec/std/crystal/system_spec.cr @@ -1,48 +1,48 @@ require "../spec_helper" -private def print_error_to_s(format, *args) +private def printf_to_s(format, *args) io = IO::Memory.new - Crystal::System.print_error(format, *args) do |bytes| + Crystal::System.printf(format, *args) do |bytes| io.write_string(bytes) end io.to_s end describe "Crystal::System" do - describe ".print_error" do + describe ".printf" do it "works" do - print_error_to_s("abcde").should eq("abcde") + printf_to_s("abcde").should eq("abcde") end it "supports %d" do - print_error_to_s("%d,%d,%d,%d,%d", 0, 1234, Int32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,2147483647,-2147483648,-1") + printf_to_s("%d,%d,%d,%d,%d", 0, 1234, Int32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,2147483647,-2147483648,-1") end it "supports %u" do - print_error_to_s("%u,%u,%u,%u,%u", 0, 1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,4294967295,2147483648,4294967295") + printf_to_s("%u,%u,%u,%u,%u", 0, 1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,4294967295,2147483648,4294967295") end it "supports %x" do - print_error_to_s("%x,%x,%x,%x,%x", 0, 0x1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,ffffffff,80000000,ffffffff") + printf_to_s("%x,%x,%x,%x,%x", 0, 0x1234, UInt32::MAX, Int32::MIN, UInt64::MAX).should eq("0,1234,ffffffff,80000000,ffffffff") end # TODO: investigate why this prints `(???)` pending_interpreted "supports %p" do - print_error_to_s("%p,%p,%p", Pointer(Void).new(0x0), Pointer(Void).new(0x1234), Pointer(Void).new(UInt64::MAX)).should eq("0x0,0x1234,0xffffffffffffffff") + printf_to_s("%p,%p,%p", Pointer(Void).new(0x0), Pointer(Void).new(0x1234), Pointer(Void).new(UInt64::MAX)).should eq("0x0,0x1234,0xffffffffffffffff") end it "supports %s" do - print_error_to_s("%s,%s,%s", "abc\0def", "ghi".to_unsafe, Pointer(UInt8).null).should eq("abc\0def,ghi,(null)") + printf_to_s("%s,%s,%s", "abc\0def", "ghi".to_unsafe, Pointer(UInt8).null).should eq("abc\0def,ghi,(null)") end # BUG: missing downcast_distinct from Tuple(Int64 | UInt64, Int64 | UInt64, Int64 | UInt64, Int64 | UInt64) to Tuple(Int64, Int64, Int64, Int64) pending_interpreted "supports %l width" do values = {LibC::Long::MIN, LibC::Long::MAX, LibC::LongLong::MIN, LibC::LongLong::MAX} - print_error_to_s("%ld,%ld,%lld,%lld", *values).should eq(values.join(',')) + printf_to_s("%ld,%ld,%lld,%lld", *values).should eq(values.join(',')) values = {LibC::ULong::MIN, LibC::ULong::MAX, LibC::ULongLong::MIN, LibC::ULongLong::MAX} - print_error_to_s("%lu,%lu,%llu,%llu", *values).should eq(values.join(',')) - print_error_to_s("%lx,%lx,%llx,%llx", *values).should eq(values.join(',', &.to_s(16))) + printf_to_s("%lu,%lu,%llu,%llu", *values).should eq(values.join(',')) + printf_to_s("%lx,%lx,%llx,%llx", *values).should eq(values.join(',', &.to_s(16))) end end end diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index d3bd9dc946a3..3862bb425059 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -1,29 +1,9 @@ require "colorize" +require "string_pool" module Crystal module Tracing - # List of known words used by trace calls, so we can return static strings - # instead of dynamically allocating the same few strings over an over. This - # dramatically improves performance when parsing large traces. - WORDS_DICTIONNARY = %w[ - gc - malloc - realloc - collect:mark - collect:sweep - collect - - sched - heap_resize - spawn - enqueue - resume - reschedule - sleep - event_loop - mt:sleeping - mt:slept - ] + WORDS_DICTIONNARY = StringPool.new class Values(T) getter size : T = T.zero @@ -132,16 +112,16 @@ module Crystal t = parse_char('t', 'd') expect '=' - time = parse_float + time = parse_integer / 1_000_000_000 # nanoseconds Event.new(section, action, t, time, line) end - def self.parse_variable(line : String, name : String) : Float64? + def self.parse_variable(line : String, name : String) : Int64? if pos = line.index(name) reader = Char::Reader.new(line, pos + name.bytesize + 1) expect '=' - parse_float + parse_integer end end @@ -150,48 +130,35 @@ module Crystal # allocate a string. private macro parse_word pos = reader.pos - case - {% for word in WORDS_DICTIONNARY %} - when parse_word?({{word}}) - {{word}} - {% end %} - else - loop do - %char = reader.current_char - return unless %char.ascii_letter? || {'-', '_', ':'}.includes?(%char) - break if reader.next_char == ' ' - end - reader.string[pos...reader.pos] + + loop do + %char = reader.current_char + return unless %char.ascii_letter? || {'-', '_', ':'}.includes?(%char) + break if reader.next_char == ' ' end + + WORDS_DICTIONNARY.get(reader.string.to_slice[pos...reader.pos]) end - private macro parse_word?(string) - %valid = true - {{string}}.each_char do |%char| - if reader.current_char == %char - reader.next_char - else - reader.pos = pos - %valid = false - break - end + # Parses an integer directly without allocating a dynamic string. + private macro parse_integer + %int = 0_i64 + %neg = false + + if reader.current_char == '-' + reader.next_char + %neg = true + elsif reader.current_char == '+' + reader.next_char end - %valid - end - # Parses a float directly using a stack allocated buffer instead of - # allocating a dynamic string. - private macro parse_float - %buf = uninitialized UInt8[128] - %i = -1 - loop do - %char = reader.current_char - return unless %char.ascii_number? || %char == '.' - %buf[%i += 1] = %char.ord.to_u8! - break if reader.next_char == ' ' + %char = reader.current_char + while %char.ascii_number? + %int = %int * 10_i64 + %char.to_i64 + %char = reader.next_char end - %buf[%i] = 0_u8 - LibC.strtod(%buf, nil) + + %neg ? -%int : %int end private macro parse_t @@ -306,9 +273,9 @@ module Crystal data.events += 1 if @fast - data.duration += event.time.to_f if event.t == 'd' + data.duration += event.time if event.t == 'd' else - data.durations << event.time.to_f if event.t == 'd' + data.durations << event.time if event.t == 'd' end next if @fast @@ -316,7 +283,7 @@ module Crystal if event.section == "gc" if event.action == "malloc" if size = event.variable("size") - data.sizes << size.to_i + data.sizes << size.to_i32 end end end diff --git a/src/concurrent.cr b/src/concurrent.cr index 44821a67f387..3e697991b54a 100644 --- a/src/concurrent.cr +++ b/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=%lx", fiber.object_id + Crystal.trace "sched", "spawn", "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" {% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %} fiber.enqueue fiber diff --git a/src/crystal/scheduler.cr b/src/crystal/scheduler.cr index 53dbf153f196..29bf75247abb 100644 --- a/src/crystal/scheduler.cr +++ b/src/crystal/scheduler.cr @@ -25,7 +25,7 @@ class Crystal::Scheduler end def self.enqueue(fiber : Fiber) : Nil - Crystal.trace "sched", "enqueue", "fiber=%lx", fiber.object_id do + Crystal.trace "sched", "enqueue", "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" do thread = Thread.current scheduler = thread.scheduler @@ -61,7 +61,7 @@ class Crystal::Scheduler end def self.sleep(time : Time::Span) : Nil - Crystal.trace "sched", "sleep", "%.9f", time.to_f + Crystal.trace "sched", "sleep", "duration=%lld", time.total_nanoseconds.to_i64! Thread.current.scheduler.sleep(time) end @@ -115,7 +115,7 @@ class Crystal::Scheduler end protected def resume(fiber : Fiber) : Nil - Crystal.trace "sched", "resume", "fiber=%lx", fiber.object_id + Crystal.trace "sched", "resume", "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" validate_resumable(fiber) {% if flag?(:preview_mt) %} diff --git a/src/crystal/system/print_error.cr b/src/crystal/system/print_error.cr index 390eea492097..f58bef1c4ff6 100644 --- a/src/crystal/system/print_error.cr +++ b/src/crystal/system/print_error.cr @@ -3,16 +3,18 @@ module Crystal::System # This is useful for error messages from components that are required for # IO to work (fibers, scheduler, event_loop). def self.print_error(message, *args) - print_error(message, *args) do |bytes| - {% if flag?(:unix) || flag?(:wasm32) %} - LibC.write 2, bytes, bytes.size - {% elsif flag?(:win32) %} - LibC.WriteFile(LibC.GetStdHandle(LibC::STD_ERROR_HANDLE), bytes, bytes.size, out _, nil) - {% end %} - end + printf(message, *args) { |bytes| print_error(bytes) } + end + + def self.print_error(bytes : Bytes) : Nil + {% if flag?(:unix) || flag?(:wasm32) %} + LibC.write 2, bytes, bytes.size + {% elsif flag?(:win32) %} + LibC.WriteFile(LibC.GetStdHandle(LibC::STD_ERROR_HANDLE), bytes, bytes.size, out _, nil) + {% end %} end - # Minimal drop-in replacement for a C `printf` function. Yields successive + # Minimal drop-in replacement for C `printf` function. Yields successive # non-empty `Bytes` to the block, which should do the actual printing. # # *format* only supports the `%(l|ll)?[dpsux]` format specifiers; more should @@ -23,9 +25,9 @@ module Crystal::System # corrupted heap, its implementation should be as low-level as possible, # avoiding memory allocations. # - # NOTE: C's `printf` is incompatible with Crystal's `sprintf`, because the - # latter does not support argument width specifiers nor `%p`. - def self.print_error(format, *args, &) + # NOTE: Crystal's `printf` only supports a subset of C's `printf` format specifiers. + # NOTE: MSVC uses `%X` rather than `0x%x`, we follow the latter on all platforms. + def self.printf(format, *args, &) format = to_string_slice(format) format_len = format.size ptr = format.to_unsafe @@ -73,7 +75,6 @@ module Crystal::System end when 'p' read_arg(Pointer(Void)) do |arg| - # NOTE: MSVC uses `%X` rather than `0x%x`, we follow the latter on all platforms yield "0x".to_slice to_int_slice(arg.address, 16, false, 2) { |bytes| yield bytes } end diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index 3849192def6b..25654cfb19ae 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -1,9 +1,45 @@ module Crystal + # IO-like object with a fixed size. Stops writing to the internal buffer + # when capacity is reached. Any further writes are skipped. + struct StaticIO(N) + getter size : Int32 + + def initialize + @buf = uninitialized UInt8[N] + @size = 0 + end + + def write(str : String) : Nil + write str.to_slice + 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 to_slice : Bytes + Bytes.new(@buf.to_unsafe, @size) + end + end + {% if flag?(:tracing) %} # :nodoc: module Tracing - # Setups tracing, parsing the CRYSTAL_TRACE environment variable to enable - # the sections to trace (`gc` and/or `sched`). + @@tick = uninitialized Time::Span + + @[AlwaysInline] + def self.tick : Time::Span + @@tick + end + + # Setups tracing, parsing the `CRYSTAL_TRACE` environment variable to + # enable the sections to trace (`gc` and/or `sched`). # # 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 @@ -11,6 +47,7 @@ module Crystal def self.init @@gc = false @@sched = false + @@tick = Time.monotonic {% if flag?(:win32) %} buf = uninitialized UInt8[256] @@ -26,17 +63,20 @@ module Crystal return unless debug each_token(debug) do |token| - @@gc = true if token == "gc".to_slice - @@sched = true if token == "sched".to_slice + if token == "gc".to_slice + @@gc = true + elsif token == "sched".to_slice + @@sched = true + end end end def self.enabled?(section : String) : Bool case section when "gc" - !!@@gc + @@gc == true when "sched" - !!@@sched + @@sched == true else false end @@ -51,36 +91,37 @@ module Crystal end # Formats and prints a log message to STDERR. The generated message is - # limited to 511 bytes after which it will be truncated. + # limited to 512 bytes (PIPE_BUF) after which it will be truncated. # - # Doesn't use `dprintf(2)` that may do multiple writes to fd, leading to - # smashed log lines with multithreading, we prefer to use `snprintf(2)` with - # a stack allocated buffer that has a maximum size of PIPE_BUF bytes minus - # one byte for the terminating null byte (targets such as linux have a - # pipe buf of 4096 but I chose a conservative number that should be large - # enough). + # Doesn't use `dprintf(2)` nor `Crystal::System.print_error` that will + # write multiple times to fd, leading to smashed log lines with + # multithreading, we prefer to use `Crystal::System.printf` to format the + # string into a stack allocated buffer that has a maximum size of + # PIPE_BUF bytes. # - # Eventually writes to STDERR in a single write operation, this should be - # atomic since the buffer is smaller than of equal to PIPE_BUF (on POSIX - # platforms at least). + # Eventually writes to STDERR in a single write operation, which should be + # atomic since the buffer is lower than of equal to PIPE_BUF. # # Doesn't continue to write on partial writes (e.g. interrupted by a signal) # as the output could be smashed with a parallel write. def self.log(format : String, *args) : Nil - buffer = uninitialized UInt8[512] - - len = LibC.snprintf(buffer, buffer.size, format, *args) - return if len == 0 - - {% if flag?(:win32) %} - # FIXME: atomicity of _write on win32? - LibC._write(2, buffer, len) - {% else %} - LibC.write(2, buffer, len) - {% end %} + buf = StaticIO(512).new + Crystal::System.printf(format, *args) { |bytes| buf.write bytes } + Crystal::System.print_error(buf.to_slice) end end + # The *format* argument only accepts a subset of printf modifiers (namely + # `spdux` plus the `l` and `ll` length modifiers). + # + # When *block* is present, measures how long the block takes then writes + # the trace to the standard error. Otherwise immediately writes a trace to + # the standard error. + # + # Prepends *format* with the timing (current monotonic time or duration) + # along with thread and scheduler information (when present). + # + # Does nothing when tracing is disabled for the section. macro trace(section, action, format = "", *args, &block) if ::Crystal::Tracing.enabled?(\{{section}}) \{% if block %} @@ -91,7 +132,7 @@ module Crystal %ret \{% else %} %tick = ::Time.monotonic - ::Crystal.trace_end('t', %tick, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + ::Crystal.trace_end('t', %tick - ::Crystal::Tracing.tick, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) nil \{% end %} else @@ -99,29 +140,42 @@ module Crystal end end + # :nodoc: macro trace_end(t, tick_or_duration, section, action, format = "", *args) - # we may 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 are allocate (otherwise we hit infinite - # recursion): malloc -> trace -> malloc -> trace -> ... - if %thread = Thread.current? - if %scheduler = %thread.scheduler? - %fiber = %scheduler.@current - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx fiber=%lx [%s] \{{format.id}}\n", - (\{{tick_or_duration}}).to_f, %thread, %fiber.object_id, %fiber.name || "", \{{args.splat}}) + {% if flag?(:wasm32) %} + # WASM doesn't have threads (and fibers aren't implemented either) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f \{{format.id}}\n", + (\{{tick_or_duration}}).to_f, \{{args.splat}}) + {% else %} + {% thread_type = flag?(:linux) ? "0x%lx".id : "%p".id %} + # TODO: thread name (when present) + + # we may 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 -> ... + if %thread = Thread.current? + if %fiber = %thread.current_fiber? + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%lld thread={{thread_type}} [%s] fiber=%p [%s] \{{format.id}}\n", + (\{{tick_or_duration}}).total_nanoseconds.to_i64!, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{args.splat}}) + else + # fallback: no current fiber for the current thread (yet) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%lld thread={{thread_type}} [%s] \{{format.id}}\n", + (\{{tick_or_duration}}).total_nanoseconds.to_i64!, %thread.@system_handle, %thread.name || "?", \{{args.splat}}) + end else - # fallback: no scheduler (or not started yet?) for the current thread - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", - (\{{tick_or_duration}}).to_f, %thread, \{{args.splat}}) + # fallback: no Thread object (yet) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%lld thread={{thread_type}} [%s] \{{format.id}}\n", + (\{{tick_or_duration}}).total_nanoseconds.to_i64!, Crystal::System::Thread.current_handle, "?", \{{args.splat}}) end - else - # fallback: no Thread object (yet) - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f thread=%lx \{{format.id}}\n", - (\{{tick_or_duration}}).to_f, Crystal::System::Thread.current_handle, \{{args.splat}}) - end + {% end %} end {% else %} + # :nodoc: module Tracing + def self.init + end + def self.enabled?(section) false end @@ -134,6 +188,7 @@ module Crystal \{{yield}} end + # :nodoc: macro trace_end(t, tick_or_duration, section, action, format = "", *args) end {% end %} From 49101bf7e7fbe6528120f460be661d9c271a1a8b Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Thu, 16 May 2024 14:44:37 +0200 Subject: [PATCH 10/20] Fix: some win32 fixes --- src/crystal/system/win32/thread.cr | 6 ++++++ src/crystal/system/win32/time.cr | 18 ++++++++++-------- src/crystal/tracing.cr | 13 ++++++++----- 3 files changed, 24 insertions(+), 13 deletions(-) diff --git a/src/crystal/system/win32/thread.cr b/src/crystal/system/win32/thread.cr index 2b44f66c28ce..0715906abade 100644 --- a/src/crystal/system/win32/thread.cr +++ b/src/crystal/system/win32/thread.cr @@ -47,6 +47,12 @@ module Crystal::System::Thread @[ThreadLocal] class_property current_thread : ::Thread { ::Thread.new } + {% if flag?(:tracing) %} + def self.current_thread? : ::Thread? + @@current_thread + end + {% end %} + private def system_join : Exception? if LibC.WaitForSingleObject(@system_handle, LibC::INFINITE) != LibC::WAIT_OBJECT_0 return RuntimeError.from_winerror("WaitForSingleObject") diff --git a/src/crystal/system/win32/time.cr b/src/crystal/system/win32/time.cr index 358cc79a4926..d0abdae3f35c 100644 --- a/src/crystal/system/win32/time.cr +++ b/src/crystal/system/win32/time.cr @@ -53,21 +53,23 @@ module Crystal::System::Time ((filetime.dwHighDateTime.to_u64 << 32) | filetime.dwLowDateTime.to_u64).to_f64 / FILETIME_TICKS_PER_SECOND.to_f64 end - @@performance_frequency : Int64 = begin - ret = LibC.QueryPerformanceFrequency(out frequency) - if ret == 0 - raise RuntimeError.from_winerror("QueryPerformanceFrequency") - end + @@performance_frequency : Int64? - frequency + private def self.performance_frequency + @@performance_frequency ||= begin + if LibC.QueryPerformanceFrequency(out frequency) == 0 + raise RuntimeError.from_winerror("QueryPerformanceFrequency") + end + frequency + end end def self.monotonic : {Int64, Int32} if LibC.QueryPerformanceCounter(out ticks) == 0 raise RuntimeError.from_winerror("QueryPerformanceCounter") end - - {ticks // @@performance_frequency, (ticks.remainder(@@performance_frequency) * NANOSECONDS_PER_SECOND / @@performance_frequency).to_i32} + frequency = performance_frequency + {ticks // frequency, (ticks.remainder(frequency) * NANOSECONDS_PER_SECOND / frequency).to_i32} end def self.load_localtime : ::Time::Location? diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index 25654cfb19ae..b4d8527f223a 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -31,6 +31,8 @@ module Crystal {% if flag?(:tracing) %} # :nodoc: module Tracing + @@gc = uninitialized Bool + @@sched = uninitialized Bool @@tick = uninitialized Time::Span @[AlwaysInline] @@ -45,14 +47,15 @@ module Crystal # itself is initialized. The function assumes neither the GC nor ENV nor # anything is available. def self.init - @@gc = false - @@sched = false + @@gc = true + @@sched = true @@tick = Time.monotonic {% if flag?(:win32) %} - buf = uninitialized UInt8[256] - len = LibC.GetEnvironmentVariableW("CRYSTAL_TRACE", buf, buf.size) - debug = buf.to_slice(len) if len > 0 + 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) + debug = buf.to_slice[0...len] if len > 0 {% else %} if ptr = LibC.getenv("CRYSTAL_TRACE") len = LibC.strlen(ptr) From fca76625742078e770f35128b6b81614d3af28c0 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Thu, 16 May 2024 18:25:30 +0200 Subject: [PATCH 11/20] Always report both time and duration --- src/compiler/crystal/tools/tracing.cr | 30 ++++++++++------- src/crystal/tracing.cr | 48 ++++++++++++++------------- src/gc/boehm.cr | 6 ++-- 3 files changed, 46 insertions(+), 38 deletions(-) diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index 3862bb425059..dac59e484983 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -103,18 +103,18 @@ module Crystal module Parser def self.parse_event(line : String) : Event? reader = Char::Reader.new(line) - section = parse_word expect ' ' - action = parse_word expect ' ' - - t = parse_char('t', 'd') + expect 't' expect '=' time = parse_integer / 1_000_000_000 # nanoseconds - - Event.new(section, action, t, time, line) + expect ' ' + expect 'd' + expect '=' + duration = parse_integer / 1_000_000_000 # nanoseconds + Event.new(section, action, time, duration, line) end def self.parse_variable(line : String, name : String) : Int64? @@ -193,16 +193,20 @@ module Crystal struct Event getter section : String getter action : String - getter t : Char getter time : Float64 + @duration : Float64 getter line : String - def initialize(@section, @action, @t, @time, @line) + def initialize(@section, @action, @time, @duration, @line) end def variable(name : String) Parser.parse_variable(line, name) end + + def duration? + @duration unless @duration.negative? + end end class Data @@ -272,10 +276,12 @@ module Crystal data = stats[event.section][event.action] data.events += 1 - if @fast - data.duration += event.time if event.t == 'd' - else - data.durations << event.time if event.t == 'd' + if duration = event.duration? + if @fast + data.duration += duration + else + data.durations << duration + end end next if @fast diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index b4d8527f223a..f7d673018aef 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -107,35 +107,35 @@ module Crystal # # Doesn't continue to write on partial writes (e.g. interrupted by a signal) # as the output could be smashed with a parallel write. - def self.log(format : String, *args) : Nil + def self.log(fmt : String, *args) : Nil buf = StaticIO(512).new - Crystal::System.printf(format, *args) { |bytes| buf.write bytes } + Crystal::System.printf(fmt, *args) { |bytes| buf.write bytes } Crystal::System.print_error(buf.to_slice) end end - # The *format* argument only accepts a subset of printf modifiers (namely + # The *fmt* argument only accepts a subset of printf modifiers (namely # `spdux` plus the `l` and `ll` length modifiers). # # When *block* is present, measures how long the block takes then writes # the trace to the standard error. Otherwise immediately writes a trace to # the standard error. # - # Prepends *format* with the timing (current monotonic time or duration) + # Prepends *fmt* with the timing (current monotonic time or duration) # along with thread and scheduler information (when present). # # Does nothing when tracing is disabled for the section. - macro trace(section, action, format = "", *args, &block) + macro trace(section, action, fmt = "", *args, &block) if ::Crystal::Tracing.enabled?(\{{section}}) + %tick = ::Time.monotonic + %time = %tick - ::Crystal::Tracing.tick \{% if block %} - %start = ::Time.monotonic %ret = \{{yield}} - %stop = ::Time.monotonic - ::Crystal.trace_end('d', %stop - %start, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + %duration = ::Time.monotonic - %tick + ::Crystal.trace_end(%time, %duration, \{{section}}, \{{action}}, \{{fmt}}, \{{args.splat}}) %ret \{% else %} - %tick = ::Time.monotonic - ::Crystal.trace_end('t', %tick - ::Crystal::Tracing.tick, \{{section}}, \{{action}}, \{{format}}, \{{args.splat}}) + ::Crystal.trace_end(%time, nil, \{{section}}, \{{action}}, \{{fmt}}, \{{args.splat}}) nil \{% end %} else @@ -144,14 +144,16 @@ module Crystal end # :nodoc: - macro trace_end(t, tick_or_duration, section, action, format = "", *args) + macro trace_end(time, duration, section, action, fmt = "", *args) + %time = (\{{time}}).total_nanoseconds.to_i64! + %duration = (\{{duration}}).try(&.total_nanoseconds.to_i64!) || -1_i64 + {% if flag?(:wasm32) %} # WASM doesn't have threads (and fibers aren't implemented either) - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%.9f \{{format.id}}\n", - (\{{tick_or_duration}}).to_f, \{{args.splat}}) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld \{{fmt.id}}\n", + %time, %duration, \{{args.splat}}) {% else %} {% thread_type = flag?(:linux) ? "0x%lx".id : "%p".id %} - # TODO: thread name (when present) # we may start to trace *before* Thread.current and other objects have # been allocated, they're lazily allocated and since we trace GC.malloc we @@ -159,17 +161,17 @@ module Crystal # recursion): malloc -> trace -> malloc -> trace -> ... if %thread = Thread.current? if %fiber = %thread.current_fiber? - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%lld thread={{thread_type}} [%s] fiber=%p [%s] \{{format.id}}\n", - (\{{tick_or_duration}}).total_nanoseconds.to_i64!, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{args.splat}}) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld thread={{thread_type}} [%s] fiber=%p [%s] \{{fmt.id}}\n", + %time, %duration, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{args.splat}}) else # fallback: no current fiber for the current thread (yet) - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%lld thread={{thread_type}} [%s] \{{format.id}}\n", - (\{{tick_or_duration}}).total_nanoseconds.to_i64!, %thread.@system_handle, %thread.name || "?", \{{args.splat}}) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld thread={{thread_type}} [%s] \{{fmt.id}}\n", + %time, %duration, %thread.@system_handle, %thread.name || "?", \{{args.splat}}) end else # fallback: no Thread object (yet) - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} \{{t.id}}=%lld thread={{thread_type}} [%s] \{{format.id}}\n", - (\{{tick_or_duration}}).total_nanoseconds.to_i64!, Crystal::System::Thread.current_handle, "?", \{{args.splat}}) + ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld thread={{thread_type}} [%s] \{{fmt.id}}\n", + %time, %duration, Crystal::System::Thread.current_handle, "?", \{{args.splat}}) end {% end %} end @@ -183,16 +185,16 @@ module Crystal false end - def self.log(format : String, *args) + def self.log(fmt : String, *args) end end - macro trace(section, action, format = "", *args, &block) + macro trace(section, action, fmt = "", *args, &block) \{{yield}} end # :nodoc: - macro trace_end(t, tick_or_duration, section, action, format = "", *args) + macro trace_end(t, tick_or_duration, section, action, fmt = "", *args) end {% end %} end diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr index 7330235a9107..0098a3df862a 100644 --- a/src/gc/boehm.cr +++ b/src/gc/boehm.cr @@ -252,13 +252,13 @@ module GC @@sweep_start = Time.monotonic when .end? duration = ::Time.monotonic - @@collect_start - Crystal.trace_end 'd', duration, "gc", "collect" + Crystal.trace_end @@collect_start, duration, "gc", "collect" when .mark_end? duration = ::Time.monotonic - @@mark_start - Crystal.trace_end 'd', duration, "gc", "collect:mark" + Crystal.trace_end @@collect_start, duration, "gc", "collect:mark" when .reclaim_end? duration = ::Time.monotonic - @@sweep_start - Crystal.trace_end 'd', duration, "gc", "collect:sweep" + Crystal.trace_end @@collect_start, duration, "gc", "collect:sweep" end @@on_collection_event.try(&.call(event_type)) }) From d1f619981571c02bea43e4721ae76ca8c5b12f82 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Thu, 16 May 2024 18:56:45 +0200 Subject: [PATCH 12/20] A couple simplifications --- src/compiler/crystal/tools/tracing.cr | 22 ++++----- src/crystal/tracing.cr | 66 +++++++++------------------ 2 files changed, 33 insertions(+), 55 deletions(-) diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index dac59e484983..129984a31259 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -76,7 +76,7 @@ module Crystal end end - class Sizes < Values(UInt64) + class Sizes < Values(Int64) KILOBYTE = 1024 MEGABYTE = 1024 * 1024 GIGABYTE = 1024 * 1024 * 1024 @@ -105,7 +105,7 @@ module Crystal reader = Char::Reader.new(line) section = parse_word expect ' ' - action = parse_word + operation = parse_word expect ' ' expect 't' expect '=' @@ -114,12 +114,12 @@ module Crystal expect 'd' expect '=' duration = parse_integer / 1_000_000_000 # nanoseconds - Event.new(section, action, time, duration, line) + Event.new(section, operation, time, duration, line) end def self.parse_variable(line : String, name : String) : Int64? if pos = line.index(name) - reader = Char::Reader.new(line, pos + name.bytesize + 1) + reader = Char::Reader.new(line, pos + name.bytesize) expect '=' parse_integer end @@ -192,12 +192,12 @@ module Crystal struct Event getter section : String - getter action : String + getter operation : String getter time : Float64 @duration : Float64 getter line : String - def initialize(@section, @action, @time, @duration, @line) + def initialize(@section, @operation, @time, @duration, @line) end def variable(name : String) @@ -273,7 +273,7 @@ module Crystal end each_event do |event| - data = stats[event.section][event.action] + data = stats[event.section][event.operation] data.events += 1 if duration = event.duration? @@ -287,18 +287,18 @@ module Crystal next if @fast if event.section == "gc" - if event.action == "malloc" + if event.operation == "malloc" if size = event.variable("size") - data.sizes << size.to_i32 + data.sizes << size end end end end stats.each do |section, actions| - actions.each do |action, data| + actions.each do |operation, data| Colorize.with.toggle(@color).yellow.surround(@stdout) do - @stdout << section << ':' << action + @stdout << section << ':' << operation end data.each do |key, value| diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index f7d673018aef..c44723612ebb 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -45,7 +45,7 @@ module Crystal # # 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. + # anything is available and musn't allocate into the GC HEAP. def self.init @@gc = true @@sched = true @@ -93,20 +93,13 @@ module Crystal yield bytes[0..] unless bytes.size == 0 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. + # 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. # - # Doesn't use `dprintf(2)` nor `Crystal::System.print_error` that will - # write multiple times to fd, leading to smashed log lines with - # multithreading, we prefer to use `Crystal::System.printf` to format the - # string into a stack allocated buffer that has a maximum size of - # PIPE_BUF bytes. - # - # Eventually writes to STDERR in a single write operation, which should be - # atomic since the buffer is lower than of equal to PIPE_BUF. - # - # Doesn't continue to write on partial writes (e.g. interrupted by a signal) - # as the output could be smashed with a parallel write. + # Windows may not have the same guarantees but the buffering should limit + # these from happening. def self.log(fmt : String, *args) : Nil buf = StaticIO(512).new Crystal::System.printf(fmt, *args) { |bytes| buf.write bytes } @@ -114,28 +107,17 @@ module Crystal end end - # The *fmt* argument only accepts a subset of printf modifiers (namely - # `spdux` plus the `l` and `ll` length modifiers). - # - # When *block* is present, measures how long the block takes then writes - # the trace to the standard error. Otherwise immediately writes a trace to - # the standard error. - # - # Prepends *fmt* with the timing (current monotonic time or duration) - # along with thread and scheduler information (when present). - # - # Does nothing when tracing is disabled for the section. - macro trace(section, action, fmt = "", *args, &block) + macro trace(section, operation, fmt = "", *args, &block) if ::Crystal::Tracing.enabled?(\{{section}}) %tick = ::Time.monotonic %time = %tick - ::Crystal::Tracing.tick \{% if block %} %ret = \{{yield}} %duration = ::Time.monotonic - %tick - ::Crystal.trace_end(%time, %duration, \{{section}}, \{{action}}, \{{fmt}}, \{{args.splat}}) + ::Crystal.trace_end(%time, %duration, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}}) %ret \{% else %} - ::Crystal.trace_end(%time, nil, \{{section}}, \{{action}}, \{{fmt}}, \{{args.splat}}) + ::Crystal.trace_end(%time, nil, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}}) nil \{% end %} else @@ -144,13 +126,13 @@ module Crystal end # :nodoc: - macro trace_end(time, duration, section, action, fmt = "", *args) + macro trace_end(time, duration, section, operation, fmt = "", *args) %time = (\{{time}}).total_nanoseconds.to_i64! %duration = (\{{duration}}).try(&.total_nanoseconds.to_i64!) || -1_i64 {% if flag?(:wasm32) %} # WASM doesn't have threads (and fibers aren't implemented either) - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld \{{fmt.id}}\n", + ::Crystal::Tracing.log("\{{section.id}} \{{operation.id}} t=%lld d=%lld \{{fmt.id}}\n", %time, %duration, \{{args.splat}}) {% else %} {% thread_type = flag?(:linux) ? "0x%lx".id : "%p".id %} @@ -159,19 +141,15 @@ module Crystal # 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 -> ... - if %thread = Thread.current? - if %fiber = %thread.current_fiber? - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld thread={{thread_type}} [%s] fiber=%p [%s] \{{fmt.id}}\n", - %time, %duration, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{args.splat}}) - else - # fallback: no current fiber for the current thread (yet) - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld thread={{thread_type}} [%s] \{{fmt.id}}\n", - %time, %duration, %thread.@system_handle, %thread.name || "?", \{{args.splat}}) - end + if (%thread = Thread.current?) && (%fiber = %thread.current_fiber?) + ::Crystal::Tracing.log( + "\{{section.id}} \{{operation.id}} t=%lld d=%lld thread={{thread_type}} [%s] fiber=%p [%s] \{{fmt.id}}\n", + %time, %duration, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{args.splat}}) else - # fallback: no Thread object (yet) - ::Crystal::Tracing.log("\{{section.id}} \{{action.id}} t=%lld d=%lld thread={{thread_type}} [%s] \{{fmt.id}}\n", - %time, %duration, Crystal::System::Thread.current_handle, "?", \{{args.splat}}) + %thread_handle = %thread ? %thread.@system_handle : Crystal::System::Thread.current_handle + ::Crystal::Tracing.log( + "\{{section.id}} \{{operation.id}} t=%lld d=%lld thread={{thread_type}} [%s] \{{fmt.id}}\n", + %time, %duration, %thread_handle, %thread.try(&.name) || "?", \{{args.splat}}) end {% end %} end @@ -189,12 +167,12 @@ module Crystal end end - macro trace(section, action, fmt = "", *args, &block) + macro trace(section, operation, fmt = "", *args, &block) \{{yield}} end # :nodoc: - macro trace_end(t, tick_or_duration, section, action, fmt = "", *args) + macro trace_end(t, tick_or_duration, section, operation, fmt = "", *args) end {% end %} end From a419f1784c95df7a8daff5e9c54d2e11b57b4f70 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Thu, 16 May 2024 19:17:36 +0200 Subject: [PATCH 13/20] fixup! A couple simplifications --- spec/compiler/crystal/tools/tracing_spec.cr | 44 ++++++++++----------- 1 file changed, 22 insertions(+), 22 deletions(-) diff --git a/spec/compiler/crystal/tools/tracing_spec.cr b/spec/compiler/crystal/tools/tracing_spec.cr index b146248fbaa3..bd11d433e817 100644 --- a/spec/compiler/crystal/tools/tracing_spec.cr +++ b/spec/compiler/crystal/tools/tracing_spec.cr @@ -5,14 +5,14 @@ require "../../../support/tempfile" describe Crystal::Tracing::StatsCommand do it "parses stdin" do stdin = IO::Memory.new <<-TRACE - gc malloc d=23724 thread=7f0ea62bd740 size=16 - gc malloc d=9074 thread=7f0ea62bd740 size=4 atomic=1 - gc malloc d=128 thread=7f0ea62bd740 size=144 - sched spawn t=102125792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 - sched enqueue d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 - gc malloc d=222 thread=7f0ea62bd740 size=24 - gc collect d=79489 thread=7f0ea62bd740 - gc heap_resize t=102125791993928 thread=7f0ea62bd740 size=131072 + gc malloc t=410557 d=9012 size=16 + gc malloc t=482582 d=401 size=4 atomic=1 + gc malloc t=493775 d=128 thread=7f0ea62bd740 size=144 + sched spawn t=520355 d=-1 thread=7f0ea62bd740 fiber=7f0ea6299f00 + sched enqueue t=530598 d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 + gc malloc t=550326 d=222 thread=7f0ea62bd740 size=24 + gc collect t=561057 d=79489 thread=7f0ea62bd740 + gc heap_resize t=102125791993927 d=-1 thread=7f0ea62bd740 size=131072 TRACE stdout = IO::Memory.new stderr = IO::Memory.new @@ -29,14 +29,14 @@ describe Crystal::Tracing::StatsCommand do it "--fast" do stdin = IO::Memory.new <<-TRACE - gc malloc d=23724 thread=7f0ea62bd740 size=16 - gc malloc d=9074 thread=7f0ea62bd740 size=4 atomic=1 - gc malloc d=128 thread=7f0ea62bd740 size=144 - sched spawn t=102125792579486 thread=7f0ea62bd740 fiber=7f0ea6299f00 - sched enqueue d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 - gc malloc d=222 thread=7f0ea62bd740 size=24 - gc collect d=79489 thread=7f0ea62bd740 - gc heap_resize t=102125791993928 thread=7f0ea62bd740 size=131072 + gc malloc t=410557 d=9012 size=16 + gc malloc t=482582 d=401 size=4 atomic=1 + gc malloc t=493775 d=128 thread=7f0ea62bd740 size=144 + sched spawn t=520355 d=-1 thread=7f0ea62bd740 fiber=7f0ea6299f00 + sched enqueue t=530598 d=101572 thread=7f0ea62bd740 fiber=7f0ea6299e60 [main] fiber=7f0ea6299f00 + gc malloc t=550326 d=222 thread=7f0ea62bd740 size=24 + gc collect t=561057 d=79489 thread=7f0ea62bd740 + gc heap_resize t=102125791993927 d=-1 thread=7f0ea62bd740 size=131072 TRACE stdout = IO::Memory.new stderr = IO::Memory.new @@ -58,10 +58,10 @@ describe Crystal::Tracing::StatsCommand do with_tempfile("trace.log") do |path| File.write path, <<-TRACE - gc malloc d=23724 thread=7f0ea62bd740 size=16 - gc malloc d=9074 thread=7f0ea62bd740 size=4 atomic=1 - gc malloc d=222 thread=7f0ea62bd740 size=24 - gc collect d=79489 thread=7f0ea62bd740 + gc malloc t=410557 d=23724 thread=7f0ea62bd740 size=16 + gc malloc t=482582 d=9074 thread=7f0ea62bd740 size=4 atomic=1 + gc malloc t=493775 d=222 thread=7f0ea62bd740 size=24 + gc collect t=520355 d=79489 thread=7f0ea62bd740 TRACE Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run @@ -80,7 +80,7 @@ describe Crystal::Tracing::StatsCommand do with_tempfile("trace.log") do |path| File.write path, <<-TRACE Using compiled compiler at .build/crystal - gc malloc d=23724 thread=7f0ea62bd740 size=16 + gc malloc t=410557 d=23724 thread=7f0ea62bd740 size=16 TRACE Crystal::Tracing::StatsCommand.new(path, stdin: stdin, stdout: stdout, stderr: stderr).run @@ -92,7 +92,7 @@ describe Crystal::Tracing::StatsCommand do it "skips invalid traces when parsing stdin" do stdin = IO::Memory.new <<-TRACE Using compiled compiler at .build/crystal - gc malloc d=23724 thread=7f0ea62bd740 size=16 + gc malloc t=410557 d=23724 thread=7f0ea62bd740 size=16 TRACE stdout = IO::Memory.new stderr = IO::Memory.new From 0e1ffe8d57f09564be2bb0340ad3e22732c9e6c6 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 17 May 2024 12:10:40 +0200 Subject: [PATCH 14/20] Add Crystal::Tracing::Section flags enum instead of raw strings --- src/concurrent.cr | 2 +- src/crystal/scheduler.cr | 16 +++---- src/crystal/tracing.cr | 92 +++++++++++++++++++--------------------- src/gc/boehm.cr | 18 +++----- src/gc/none.cr | 9 ++-- 5 files changed, 64 insertions(+), 73 deletions(-) diff --git a/src/concurrent.cr b/src/concurrent.cr index 3e697991b54a..9df66306bb1d 100644 --- a/src/concurrent.cr +++ b/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=%p [%s]", fiber.as(Void*), fiber.name || "?" + Crystal.trace :sched, :spawn, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" {% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %} fiber.enqueue fiber diff --git a/src/crystal/scheduler.cr b/src/crystal/scheduler.cr index 29bf75247abb..3fabc997adca 100644 --- a/src/crystal/scheduler.cr +++ b/src/crystal/scheduler.cr @@ -25,7 +25,7 @@ class Crystal::Scheduler end def self.enqueue(fiber : Fiber) : Nil - Crystal.trace "sched", "enqueue", "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" do + Crystal.trace :sched, :enqueue, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" 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", "duration=%lld", time.total_nanoseconds.to_i64! + Crystal.trace :sched, :sleep, "duration=%lld", 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=%p [%s]", fiber.as(Void*), fiber.name || "?" + Crystal.trace :sched, :resume, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" validate_resumable(fiber) {% if flag?(:preview_mt) %} @@ -156,7 +156,7 @@ class Crystal::Scheduler resume(runnable) unless runnable == @thread.current_fiber break else - Crystal.trace "sched", "event_loop" do + Crystal.trace :sched, "event_loop" do @event_loop.run_once end end @@ -200,8 +200,8 @@ class Crystal::Scheduler @sleeping = true @lock.unlock - Crystal.trace "sched", "mt:sleeping" - fiber = Crystal.trace("sched", "mt:slept") { 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/tracing.cr b/src/crystal/tracing.cr index c44723612ebb..c571aeb1905f 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -1,40 +1,47 @@ module Crystal - # IO-like object with a fixed size. Stops writing to the internal buffer - # when capacity is reached. Any further writes are skipped. - struct StaticIO(N) - getter size : Int32 - - def initialize - @buf = uninitialized UInt8[N] - @size = 0 - 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(str : String) : Nil - write str.to_slice - end + def write(bytes : Bytes) : Nil + pos = @size + remaining = N - pos + return if remaining == 0 - 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 - n = bytes.size.clamp(..remaining) - bytes.to_unsafe.copy_to(@buf.to_unsafe + pos, n) - @size = pos + n - end + def to_slice : Bytes + Bytes.new(@buf.to_unsafe, @size) + end + end - def to_slice : Bytes - Bytes.new(@buf.to_unsafe, @size) - end - end + @[Flags] + enum Section + Gc + Sched + end - {% if flag?(:tracing) %} - # :nodoc: - module Tracing - @@gc = uninitialized Bool - @@sched = uninitialized Bool + @@sections = uninitialized Section @@tick = uninitialized Time::Span + @[AlwaysInline] + def self.enabled?(section : Section) : Bool + @@sections.includes?(section) + end + @[AlwaysInline] def self.tick : Time::Span @@tick @@ -47,8 +54,7 @@ module Crystal # 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 - @@gc = true - @@sched = true + @@sections = Section::None @@tick = Time.monotonic {% if flag?(:win32) %} @@ -66,25 +72,15 @@ module Crystal return unless debug each_token(debug) do |token| - if token == "gc".to_slice - @@gc = true - elsif token == "sched".to_slice - @@sched = true + case token + when "gc".to_slice + @@sections |= Section::Gc + when "sched".to_slice + @@sections |= Section::Sched end end end - def self.enabled?(section : String) : Bool - case section - when "gc" - @@gc == true - when "sched" - @@sched == true - else - false - end - end - private def self.each_token(bytes, delim = ',', &) while e = bytes.index(delim.ord) yield bytes[0, e] @@ -101,7 +97,7 @@ module Crystal # Windows may not have the same guarantees but the buffering should limit # these from happening. def self.log(fmt : String, *args) : Nil - buf = StaticIO(512).new + buf = BufferIO(512).new Crystal::System.printf(fmt, *args) { |bytes| buf.write bytes } Crystal::System.print_error(buf.to_slice) end @@ -172,7 +168,7 @@ module Crystal end # :nodoc: - macro trace_end(t, tick_or_duration, section, operation, fmt = "", *args) + macro trace_end(time, duration, section, operation, fmt = "", *args) end {% end %} end diff --git a/src/gc/boehm.cr b/src/gc/boehm.cr index 0098a3df862a..7a0fee3b12a9 100644 --- a/src/gc/boehm.cr +++ b/src/gc/boehm.cr @@ -170,28 +170,26 @@ module GC # :nodoc: def self.malloc(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%lu", size do + Crystal.trace :gc, :malloc, "size=%lu", size do LibGC.malloc(size) end end # :nodoc: def self.malloc_atomic(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%lu atomic=1", size do + Crystal.trace :gc, :malloc, "size=%lu atomic=1", size do LibGC.malloc_atomic(size) end end # :nodoc: def self.realloc(ptr : Void*, size : LibC::SizeT) : Void* - Crystal.trace "gc", "realloc", "size=%lu", size do + Crystal.trace :gc, :realloc, "size=%lu", size do LibGC.realloc(ptr, size) end end def self.init : Nil - # Crystal.trace "gc", "init" - {% unless flag?(:win32) %} LibGC.set_handle_fork(1) {% end %} @@ -202,7 +200,7 @@ module GC end {% if flag?(:tracing) %} - if ::Crystal::Tracing.enabled?("gc") + if ::Crystal::Tracing.enabled?(:gc) set_on_heap_resize_proc set_on_collection_events_proc end @@ -232,7 +230,7 @@ module GC @@on_heap_resize = LibGC.get_on_heap_resize LibGC.set_on_heap_resize(->(new_size : LibGC::Word) { - Crystal.trace "gc", "heap_resize", "size=%llu", UInt64.new(new_size) + Crystal.trace :gc, :heap_resize, "size=%llu", UInt64.new(new_size) @@on_heap_resize.try(&.call(new_size)) }) end @@ -241,8 +239,6 @@ module GC @@on_collection_event = LibGC.get_on_collection_event LibGC.set_on_collection_event(->(event_type : LibGC::EventType) { - # Crystal.trace "gc", "on_collection_event", "type=%s", event_type.to_s - case event_type when .start? @@collect_start = Time.monotonic @@ -266,7 +262,7 @@ module GC {% end %} def self.collect - Crystal.trace "gc", "collect" do + Crystal.trace :gc, :collect do LibGC.collect end end @@ -284,7 +280,7 @@ module GC end def self.free(pointer : Void*) : Nil - Crystal.trace "gc", "free" do + Crystal.trace :gc, :free do LibGC.free(pointer) end end diff --git a/src/gc/none.cr b/src/gc/none.cr index 89de335b9caa..92585a769cc8 100644 --- a/src/gc/none.cr +++ b/src/gc/none.cr @@ -5,24 +5,23 @@ require "crystal/tracing" module GC def self.init - # Crystal.trace "gc", "init" end # :nodoc: def self.malloc(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%lu", size + Crystal.trace :gc, :malloc, "size=%lu", size LibC.malloc(size) end # :nodoc: def self.malloc_atomic(size : LibC::SizeT) : Void* - Crystal.trace "gc", "malloc", "size=%lu atomic=1", size + Crystal.trace :gc, :malloc, "size=%lu atomic=1", size LibC.malloc(size) end # :nodoc: def self.realloc(pointer : Void*, size : LibC::SizeT) : Void* - Crystal.trace "gc", "realloc", "size=%lu", size + Crystal.trace :gc, :realloc, "size=%lu", size LibC.realloc(pointer, size) end @@ -36,7 +35,7 @@ module GC end def self.free(pointer : Void*) : Nil - Crystal.trace "gc", "free" + Crystal.trace :gc, :free LibC.free(pointer) end From 95bbe81d552bfec2e13eb005b6e6b7c146b4dbbd Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 17 May 2024 12:16:37 +0200 Subject: [PATCH 15/20] Fix: always gen Thread.current_thread? and Thread#scheduler? --- src/crystal/system/thread.cr | 22 ++++++++++------------ src/crystal/system/unix/pthread.cr | 18 +++++++----------- src/crystal/system/win32/thread.cr | 8 +++----- 3 files changed, 20 insertions(+), 28 deletions(-) diff --git a/src/crystal/system/thread.cr b/src/crystal/system/thread.cr index 932a637d6507..c11f60d4afe5 100644 --- a/src/crystal/system/thread.cr +++ b/src/crystal/system/thread.cr @@ -10,6 +10,8 @@ module Crystal::System::Thread # def self.current_thread : ::Thread + # def self.current_thread? : ::Thread? + # def self.current_thread=(thread : ::Thread) # private def system_join : Exception? @@ -100,12 +102,10 @@ class Thread Crystal::System::Thread.current_thread end - {% if flag?(:tracing) %} - # :nodoc: - def self.current? : Thread? - Crystal::System::Thread.current_thread? - end - {% end %} + # :nodoc: + def self.current? : Thread? + Crystal::System::Thread.current_thread? + end # Associates the Thread object to the running system thread. protected def self.current=(current : Thread) : Thread @@ -127,12 +127,10 @@ class Thread # :nodoc: getter scheduler : Crystal::Scheduler { Crystal::Scheduler.new(self) } - {% if flag?(:tracing) %} - # :nodoc: - def scheduler? : ::Crystal::Scheduler? - @scheduler - end - {% end %} + # :nodoc: + def scheduler? : ::Crystal::Scheduler? + @scheduler + end protected def start Thread.threads.push(self) diff --git a/src/crystal/system/unix/pthread.cr b/src/crystal/system/unix/pthread.cr index 51fd7fff3aa1..4b357b04281c 100644 --- a/src/crystal/system/unix/pthread.cr +++ b/src/crystal/system/unix/pthread.cr @@ -55,13 +55,11 @@ module Crystal::System::Thread end end - {% if flag?(:tracing) %} - def self.current_thread? : ::Thread? - if ptr = LibC.pthread_getspecific(@@current_key) - ptr.as(::Thread) - end + def self.current_thread? : ::Thread? + if ptr = LibC.pthread_getspecific(@@current_key) + ptr.as(::Thread) end - {% end %} + end def self.current_thread=(thread : ::Thread) ret = LibC.pthread_setspecific(@@current_key, thread.as(Void*)) @@ -72,11 +70,9 @@ module Crystal::System::Thread @[ThreadLocal] class_property current_thread : ::Thread { ::Thread.new } - {% if flag?(:tracing) %} - def self.current_thread? : ::Thread? - @@current_thread - end - {% end %} + def self.current_thread? : ::Thread? + @@current_thread + end {% end %} private def system_join : Exception? diff --git a/src/crystal/system/win32/thread.cr b/src/crystal/system/win32/thread.cr index 0715906abade..9507e332b422 100644 --- a/src/crystal/system/win32/thread.cr +++ b/src/crystal/system/win32/thread.cr @@ -47,11 +47,9 @@ module Crystal::System::Thread @[ThreadLocal] class_property current_thread : ::Thread { ::Thread.new } - {% if flag?(:tracing) %} - def self.current_thread? : ::Thread? - @@current_thread - end - {% end %} + def self.current_thread? : ::Thread? + @@current_thread + end private def system_join : Exception? if LibC.WaitForSingleObject(@system_handle, LibC::INFINITE) != LibC::WAIT_OBJECT_0 From 6305ac7b45a1c3847ac04044de04e36a76cfb00b Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 17 May 2024 17:23:44 +0200 Subject: [PATCH 16/20] Add Crystal::System::Time.ticks It returns the current time from the monotonic clock in nanoseconds with additional guarantees that it won't raise or allocate memory. Note: the Win32 functions are guaranteed to never fail since Windows XP onwards, and on posix, clock_gettime may only fail on invalid input, so we can safely outlook errors. --- src/crystal/system/time.cr | 6 +++++ src/crystal/system/unix/time.cr | 21 +++++++++++++---- src/crystal/system/win32/time.cr | 13 ++++++----- src/crystal/tracing.cr | 39 ++++++++++++++++---------------- 4 files changed, 48 insertions(+), 31 deletions(-) diff --git a/src/crystal/system/time.cr b/src/crystal/system/time.cr index 0e127c5f7879..c2579760ef79 100644 --- a/src/crystal/system/time.cr +++ b/src/crystal/system/time.cr @@ -3,8 +3,14 @@ module Crystal::System::Time # since `0001-01-01 00:00:00`. # def self.compute_utc_seconds_and_nanoseconds : {Int64, Int32} + # Returns the current time from the monotonic clock in `{seconds, + # nanoseconds}`. # def self.monotonic : {Int64, Int32} + # Returns the current time from the monotonic clock in nanoseconds. + # Doesn't raise nor allocates GC HEAP memory. + # def self.ticks : UInt64 + # Returns a list of paths where time zone data should be looked up. # def self.zone_sources : Enumerable(String) diff --git a/src/crystal/system/unix/time.cr b/src/crystal/system/unix/time.cr index f7963f32f83f..1c582392d9c4 100644 --- a/src/crystal/system/unix/time.cr +++ b/src/crystal/system/unix/time.cr @@ -16,17 +16,18 @@ require "c/time" {% end %} module Crystal::System::Time - UnixEpochInSeconds = 62135596800_i64 + UNIX_EPOCH_IN_SECONDS = 62135596800_i64 + NANOSECONDS_PER_SECOND = 1_000_000_000 def self.compute_utc_seconds_and_nanoseconds : {Int64, Int32} {% if LibC.has_method?("clock_gettime") %} ret = LibC.clock_gettime(LibC::CLOCK_REALTIME, out timespec) raise RuntimeError.from_errno("clock_gettime") unless ret == 0 - {timespec.tv_sec.to_i64 + UnixEpochInSeconds, timespec.tv_nsec.to_i} + {timespec.tv_sec.to_i64 + UNIX_EPOCH_IN_SECONDS, timespec.tv_nsec.to_i} {% else %} ret = LibC.gettimeofday(out timeval, nil) raise RuntimeError.from_errno("gettimeofday") unless ret == 0 - {timeval.tv_sec.to_i64 + UnixEpochInSeconds, timeval.tv_usec.to_i * 1_000} + {timeval.tv_sec.to_i64 + UNIX_EPOCH_IN_SECONDS, timeval.tv_usec.to_i * 1_000} {% end %} end @@ -34,8 +35,8 @@ module Crystal::System::Time {% if flag?(:darwin) %} info = mach_timebase_info total_nanoseconds = LibC.mach_absolute_time * info.numer // info.denom - seconds = total_nanoseconds // 1_000_000_000 - nanoseconds = total_nanoseconds.remainder(1_000_000_000) + seconds = total_nanoseconds // NANOSECONDS_PER_SECOND + nanoseconds = total_nanoseconds.remainder(NANOSECONDS_PER_SECOND) {seconds.to_i64, nanoseconds.to_i32} {% else %} if LibC.clock_gettime(LibC::CLOCK_MONOTONIC, out tp) == 1 @@ -45,6 +46,16 @@ module Crystal::System::Time {% end %} end + def self.ticks : UInt64 + {% if flag?(:darwin) %} + info = mach_timebase_info + LibC.mach_absolute_time &* info.numer // info.denom + {% else %} + LibC.clock_gettime(LibC::CLOCK_MONOTONIC, out tp) + tp.tv_sec.to_u64! &* NANOSECONDS_PER_SECOND &+ tp.tv_nsec.to_u64! + {% end %} + end + def self.to_timespec(time : ::Time) t = uninitialized LibC::Timespec t.tv_sec = typeof(t.tv_sec).new(time.to_unix) diff --git a/src/crystal/system/win32/time.cr b/src/crystal/system/win32/time.cr index d0abdae3f35c..ab087c424cbf 100644 --- a/src/crystal/system/win32/time.cr +++ b/src/crystal/system/win32/time.cr @@ -57,21 +57,22 @@ module Crystal::System::Time private def self.performance_frequency @@performance_frequency ||= begin - if LibC.QueryPerformanceFrequency(out frequency) == 0 - raise RuntimeError.from_winerror("QueryPerformanceFrequency") - end + LibC.QueryPerformanceFrequency(out frequency) frequency end end def self.monotonic : {Int64, Int32} - if LibC.QueryPerformanceCounter(out ticks) == 0 - raise RuntimeError.from_winerror("QueryPerformanceCounter") - end + LibC.QueryPerformanceCounter(out ticks) frequency = performance_frequency {ticks // frequency, (ticks.remainder(frequency) * NANOSECONDS_PER_SECOND / frequency).to_i32} end + def self.ticks : UInt64 + LibC.QueryPerformanceCounter(out ticks) + ticks.to_u64! &* (NANOSECONDS_PER_SECOND // performance_frequency) + end + def self.load_localtime : ::Time::Location? if LibC.GetTimeZoneInformation(out info) != LibC::TIME_ZONE_ID_INVALID initialize_location_from_TZI(info, "Local") diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr index c571aeb1905f..de43a6dde369 100644 --- a/src/crystal/tracing.cr +++ b/src/crystal/tracing.cr @@ -34,8 +34,8 @@ module Crystal Sched end - @@sections = uninitialized Section - @@tick = uninitialized Time::Span + @@sections = Section::None + @@startup_tick = 0_u64 @[AlwaysInline] def self.enabled?(section : Section) : Bool @@ -43,8 +43,8 @@ module Crystal end @[AlwaysInline] - def self.tick : Time::Span - @@tick + def self.startup_tick : UInt64 + @@startup_tick end # Setups tracing, parsing the `CRYSTAL_TRACE` environment variable to @@ -55,7 +55,7 @@ module Crystal # anything is available and musn't allocate into the GC HEAP. def self.init @@sections = Section::None - @@tick = Time.monotonic + @@startup_tick = ::Crystal::System::Time.ticks {% if flag?(:win32) %} buf = uninitialized UInt16[256] @@ -72,12 +72,14 @@ module Crystal return unless debug each_token(debug) do |token| - case token - when "gc".to_slice - @@sections |= Section::Gc - when "sched".to_slice - @@sections |= Section::Sched - end + \{% begin %} + case token + \{% for name in Section.constants %} + when \{{name.downcase.id.stringify}}.to_slice + @@sections |= Section::\{{name.id}} + \{% end %} + end + \{% end %} end end @@ -105,11 +107,11 @@ module Crystal macro trace(section, operation, fmt = "", *args, &block) if ::Crystal::Tracing.enabled?(\{{section}}) - %tick = ::Time.monotonic - %time = %tick - ::Crystal::Tracing.tick + %tick = ::Crystal::System::Time.ticks + %time = %tick - ::Crystal::Tracing.startup_tick \{% if block %} %ret = \{{yield}} - %duration = ::Time.monotonic - %tick + %duration = ::Crystal::System::Time.ticks - %tick ::Crystal.trace_end(%time, %duration, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}}) %ret \{% else %} @@ -123,13 +125,10 @@ module Crystal # :nodoc: macro trace_end(time, duration, section, operation, fmt = "", *args) - %time = (\{{time}}).total_nanoseconds.to_i64! - %duration = (\{{duration}}).try(&.total_nanoseconds.to_i64!) || -1_i64 - {% if flag?(:wasm32) %} # WASM doesn't have threads (and fibers aren't implemented either) ::Crystal::Tracing.log("\{{section.id}} \{{operation.id}} t=%lld d=%lld \{{fmt.id}}\n", - %time, %duration, \{{args.splat}}) + \{{time}}, \{{duration}}, \{{args.splat}}) {% else %} {% thread_type = flag?(:linux) ? "0x%lx".id : "%p".id %} @@ -140,12 +139,12 @@ module Crystal if (%thread = Thread.current?) && (%fiber = %thread.current_fiber?) ::Crystal::Tracing.log( "\{{section.id}} \{{operation.id}} t=%lld d=%lld thread={{thread_type}} [%s] fiber=%p [%s] \{{fmt.id}}\n", - %time, %duration, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{args.splat}}) + \{{time}}, \{{duration}}, %thread.@system_handle, %thread.name || "?", %fiber.as(Void*), %fiber.name || "?", \{{args.splat}}) else %thread_handle = %thread ? %thread.@system_handle : Crystal::System::Thread.current_handle ::Crystal::Tracing.log( "\{{section.id}} \{{operation.id}} t=%lld d=%lld thread={{thread_type}} [%s] \{{fmt.id}}\n", - %time, %duration, %thread_handle, %thread.try(&.name) || "?", \{{args.splat}}) + \{{time}}, \{{duration}}, %thread_handle, %thread.try(&.name) || "?", \{{args.splat}}) end {% end %} end From 533a0caf9bd59d2626167c27355e7c2d827a0a78 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 17 May 2024 17:36:18 +0200 Subject: [PATCH 17/20] Fix: better specs for trace stats command --- spec/compiler/crystal/tools/tracing_spec.cr | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/spec/compiler/crystal/tools/tracing_spec.cr b/spec/compiler/crystal/tools/tracing_spec.cr index bd11d433e817..06bae67b0252 100644 --- a/spec/compiler/crystal/tools/tracing_spec.cr +++ b/spec/compiler/crystal/tools/tracing_spec.cr @@ -19,11 +19,11 @@ describe Crystal::Tracing::StatsCommand do Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run output = stdout.to_s - output.should contain("gc:malloc events=4 durations=") - output.should contain("gc:collect events=1 durations=") - output.should contain("gc:heap_resize events=1") - output.should contain("sched:spawn events=1") - output.should contain("sched:enqueue events=1 durations=") + output.should match(/^gc:malloc events=4 durations=\[.+?\] sizes=\[.+?\]$/m) + output.should match(/^gc:collect events=1 durations=\[.+?\]$/m) + output.should match(/^gc:heap_resize events=1$/m) + output.should match(/^sched:spawn events=1$/m) + output.should match(/^sched:enqueue events=1 durations=\[.+?\]$/m) stderr.to_s.should be_empty end @@ -43,11 +43,11 @@ describe Crystal::Tracing::StatsCommand do Crystal::Tracing::StatsCommand.new("-", fast: true, stdin: stdin, stdout: stdout, stderr: stderr).run output = stdout.to_s - output.should contain("gc:malloc events=4 duration=") - output.should contain("gc:collect events=1 duration=") - output.should contain("gc:heap_resize events=1") - output.should contain("sched:spawn events=1") - output.should contain("sched:enqueue events=1 duration=") + output.should match(/^gc:malloc events=4 duration=[-e\d.]+$/m) + output.should match(/^gc:collect events=1 duration=[-e\d.]+$/m) + output.should match(/^gc:heap_resize events=1$/m) + output.should match(/^sched:spawn events=1$/m) + output.should match(/^sched:enqueue events=1 duration=[-e\d.]+$/m) stderr.to_s.should be_empty end From aa4f5298adf57ed7db44313d1c8e67483ce07513 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 17 May 2024 18:32:36 +0200 Subject: [PATCH 18/20] Avoid macros + leverage humanize --- src/compiler/crystal/tools/tracing.cr | 157 ++++++++++---------------- 1 file changed, 62 insertions(+), 95 deletions(-) diff --git a/src/compiler/crystal/tools/tracing.cr b/src/compiler/crystal/tools/tracing.cr index 129984a31259..c6c8fba0ee19 100644 --- a/src/compiler/crystal/tools/tracing.cr +++ b/src/compiler/crystal/tools/tracing.cr @@ -38,7 +38,7 @@ module Crystal end def humanize(io, value) - io << value.round(9) + value.humanize(io) end def to_s(io : IO) : Nil @@ -58,134 +58,101 @@ module Crystal class Durations < Values(Float64) def humanize(io, value) - value = value.abs - - if value >= 1 - io << value.round(2) - io << 's' - elsif value > 0.001 - io << (value * 1_000).to_i64 - io << "ms" - elsif value > 0.000_001 - io << (value * 1_000_000).to_i64 - io << "us" - else - io << (value * 1_000_000_000).to_i64 - io << "ns" - end + value.humanize(io) + io << 's' end end class Sizes < Values(Int64) - KILOBYTE = 1024 - MEGABYTE = 1024 * 1024 - GIGABYTE = 1024 * 1024 * 1024 - def humanize(io, value) - value = value.abs.to_u64 - - if value >= GIGABYTE - io << (value // GIGABYTE) - io << "GB" - elsif value >= MEGABYTE - io << (value // MEGABYTE) - io << "MB" - elsif value >= KILOBYTE - io << (value // KILOBYTE) - io << "KB" - else - io << value - io << 'B' - end + value.humanize(io) + io << 'B' end end - module Parser + struct Parser def self.parse_event(line : String) : Event? - reader = Char::Reader.new(line) - section = parse_word - expect ' ' - operation = parse_word - expect ' ' - expect 't' - expect '=' - time = parse_integer / 1_000_000_000 # nanoseconds - expect ' ' - expect 'd' - expect '=' - duration = parse_integer / 1_000_000_000 # nanoseconds - Event.new(section, operation, time, duration, line) + parser = new(Char::Reader.new(line)) + parser.parse_event end def self.parse_variable(line : String, name : String) : Int64? - if pos = line.index(name) - reader = Char::Reader.new(line, pos + name.bytesize) - expect '=' - parse_integer - end + return unless pos = line.index(name) + parser = new(Char::Reader.new(line, pos + name.bytesize)) + return unless parser.expect '=' + parser.parse_integer + end + + def initialize(@reader : Char::Reader) + end + + def parse_event : Event? + return unless section = parse_word + return unless expect ' ' + return unless operation = parse_word + return unless expect ' ' + return unless expect 't' + return unless expect '=' + return unless time = parse_nanoseconds + return unless expect ' ' + return unless expect 'd' + return unless expect '=' + return unless duration = parse_nanoseconds + Event.new(section, operation, time, duration, @reader.string) end # Tries to parse known words, so we can return static strings instead of - # dynamically allocating the same string over an over, then falls back to + # dynamically allocating the same string over and over, then falls back to # allocate a string. - private macro parse_word - pos = reader.pos + protected def parse_word + pos = @reader.pos loop do - %char = reader.current_char - return unless %char.ascii_letter? || {'-', '_', ':'}.includes?(%char) - break if reader.next_char == ' ' + char = @reader.current_char + return unless char.ascii_letter? || {'-', '_', ':'}.includes?(char) + break if @reader.next_char == ' ' end - WORDS_DICTIONNARY.get(reader.string.to_slice[pos...reader.pos]) + WORDS_DICTIONNARY.get(@reader.string.to_slice[pos...@reader.pos]) end # Parses an integer directly without allocating a dynamic string. - private macro parse_integer - %int = 0_i64 - %neg = false - - if reader.current_char == '-' - reader.next_char - %neg = true - elsif reader.current_char == '+' - reader.next_char + protected def parse_integer + int = 0_i64 + neg = false + + if @reader.current_char == '-' + @reader.next_char + neg = true + elsif @reader.current_char == '+' + @reader.next_char end - %char = reader.current_char - while %char.ascii_number? - %int = %int * 10_i64 + %char.to_i64 - %char = reader.next_char + char = @reader.current_char + while char.ascii_number? + int = int * 10_i64 + char.to_i64 + char = @reader.next_char end - %neg ? -%int : %int + neg ? -int : int end - private macro parse_t - %char = reader.current_char - if {'t', 'd'}.includes?(%char) - reader.next_char - %char - else - return - end + protected def parse_nanoseconds : Float64 + parse_integer.try(&.fdiv(Time::NANOSECONDS_PER_SECOND)) end - private macro parse_char(*chars) - %char = reader.current_char - if {{chars}}.includes?(%char) - reader.next_char - %char - else - return + protected def parse_char(*chars) + char = @reader.current_char + + if chars.includes?(char) + @reader.next_char + char end end - private macro expect(char) - if reader.current_char == {{char}} - reader.next_char - else - return + protected def expect(char) + if @reader.current_char == char + @reader.next_char end end end From 6a37d38a67f3c9e11595153b6cba4760028dbe68 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 17 May 2024 18:33:41 +0200 Subject: [PATCH 19/20] fixup! Add Crystal::System::Time.ticks --- src/crystal/system/unix/time.cr | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/crystal/system/unix/time.cr b/src/crystal/system/unix/time.cr index 1c582392d9c4..58ed5b60e7e1 100644 --- a/src/crystal/system/unix/time.cr +++ b/src/crystal/system/unix/time.cr @@ -16,8 +16,8 @@ require "c/time" {% end %} module Crystal::System::Time - UNIX_EPOCH_IN_SECONDS = 62135596800_i64 - NANOSECONDS_PER_SECOND = 1_000_000_000 + UNIX_EPOCH_IN_SECONDS = 62135596800_i64 + NANOSECONDS_PER_SECOND = 1_000_000_000 def self.compute_utc_seconds_and_nanoseconds : {Int64, Int32} {% if LibC.has_method?("clock_gettime") %} From 36c502ff0790956276c6a9dacd68cc98cb832956 Mon Sep 17 00:00:00 2001 From: Julien Portalier Date: Fri, 17 May 2024 18:44:11 +0200 Subject: [PATCH 20/20] Apply suggestions from code review Co-authored-by: Sijawusz Pur Rahnama --- src/crystal/scheduler.cr | 2 +- src/crystal/system/thread.cr | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/crystal/scheduler.cr b/src/crystal/scheduler.cr index 3fabc997adca..47e470c9f50c 100644 --- a/src/crystal/scheduler.cr +++ b/src/crystal/scheduler.cr @@ -156,7 +156,7 @@ class Crystal::Scheduler resume(runnable) unless runnable == @thread.current_fiber break else - Crystal.trace :sched, "event_loop" do + Crystal.trace :sched, :event_loop do @event_loop.run_once end end diff --git a/src/crystal/system/thread.cr b/src/crystal/system/thread.cr index c11f60d4afe5..9b2a0e2ed5ca 100644 --- a/src/crystal/system/thread.cr +++ b/src/crystal/system/thread.cr @@ -128,7 +128,7 @@ class Thread getter scheduler : Crystal::Scheduler { Crystal::Scheduler.new(self) } # :nodoc: - def scheduler? : ::Crystal::Scheduler? + def scheduler? : Crystal::Scheduler? @scheduler end