diff --git a/spec/compiler/crystal/tools/tracing_spec.cr b/spec/compiler/crystal/tools/tracing_spec.cr new file mode 100644 index 000000000000..06bae67b0252 --- /dev/null +++ b/spec/compiler/crystal/tools/tracing_spec.cr @@ -0,0 +1,104 @@ +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 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 + + Crystal::Tracing::StatsCommand.new("-", stdin: stdin, stdout: stdout, stderr: stderr).run + output = stdout.to_s + 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 + + it "--fast" do + stdin = IO::Memory.new <<-TRACE + 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 + + Crystal::Tracing::StatsCommand.new("-", fast: true, stdin: stdin, stdout: stdout, stderr: stderr).run + output = stdout.to_s + 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 + + 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 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 + output = stdout.to_s + output.should contain("gc:malloc events=3 durations=") + output.should contain("gc:collect events=1 durations=") + 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 t=410557 d=23724 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 durations=") + 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 t=410557 d=23724 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 durations=") + stderr.to_s.should be_empty + end +end 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/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..26a6927e5a35 --- /dev/null +++ b/src/compiler/crystal/command/trace.cr @@ -0,0 +1,49 @@ +class Crystal::Command + private def trace + command = "stats" + color = true + fast = false + + 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("--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 + + 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::StatsCommand.new(input, fast: fast, 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..c6c8fba0ee19 --- /dev/null +++ b/src/compiler/crystal/tools/tracing.cr @@ -0,0 +1,304 @@ +require "colorize" +require "string_pool" + +module Crystal + module Tracing + WORDS_DICTIONNARY = StringPool.new + + class Values(T) + 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 + @sum_square = T.zero + end + + def <<(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 + size > 0 ? sum / size : T.zero + end + + def stddev + if size > 0 + Math.sqrt((@sum_square / size) - (average ** 2)) + else + T.zero + end + end + + def humanize(io, value) + value.humanize(io) + 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, average + io << " ±" + humanize io, stddev + io << ']' + end + end + + class Durations < Values(Float64) + def humanize(io, value) + value.humanize(io) + io << 's' + end + end + + class Sizes < Values(Int64) + def humanize(io, value) + value.humanize(io) + io << 'B' + end + end + + struct Parser + def self.parse_event(line : String) : Event? + parser = new(Char::Reader.new(line)) + parser.parse_event + end + + def self.parse_variable(line : String, name : String) : Int64? + 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 and over, then falls back to + # allocate a string. + 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 == ' ' + end + + WORDS_DICTIONNARY.get(@reader.string.to_slice[pos...@reader.pos]) + end + + # Parses an integer directly without allocating a dynamic string. + 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 + end + + neg ? -int : int + end + + protected def parse_nanoseconds : Float64 + parse_integer.try(&.fdiv(Time::NANOSECONDS_PER_SECOND)) + end + + protected def parse_char(*chars) + char = @reader.current_char + + if chars.includes?(char) + @reader.next_char + char + end + end + + protected def expect(char) + if @reader.current_char == char + @reader.next_char + end + end + end + + struct Event + getter section : String + getter operation : String + getter time : Float64 + @duration : Float64 + getter line : String + + def initialize(@section, @operation, @time, @duration, @line) + end + + def variable(name : String) + Parser.parse_variable(line, name) + end + + def duration? + @duration unless @duration.negative? + end + end + + class Data + property events : UInt64 + property duration : Float64 + getter values : Hash(Symbol, Values(Float64)) + + def initialize + @events = 0_u64 + @duration = 0_f64 + @values = {} of Symbol => Values(Float64) + end + + def durations + @durations ||= Durations.new + end + + def sizes + @sizes ||= Sizes.new + end + + def each(&) + yield :events, @events + + if durations = @durations + yield :durations, durations + elsif (duration = @duration) > 0 + yield :duration, duration.round(9) + end + + if sizes = @sizes + yield :sizes, sizes + end + + @values.each do |key, value| + yield key, value + end + end + end + + class StatsCommand + alias Action = Hash(String, Data) + alias Section = Hash(String, Action) + + @stdin : IO + @stdout : IO + @stderr : IO + + def initialize( + @path : String, + @color = false, + @fast = false, + @stdin = STDIN, + @stdout = STDOUT, + @stderr = STDERR + ) + 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 |event| + data = stats[event.section][event.operation] + data.events += 1 + + if duration = event.duration? + if @fast + data.duration += duration + else + data.durations << duration + end + end + + next if @fast + + if event.section == "gc" + if event.operation == "malloc" + if size = event.variable("size") + data.sizes << size + end + end + end + end + + stats.each do |section, actions| + actions.each do |operation, data| + Colorize.with.toggle(@color).yellow.surround(@stdout) do + @stdout << section << ':' << operation + end + + data.each do |key, value| + @stdout << ' ' << key << '=' + value.to_s(@stdout) + end + + @stdout << '\n' + end + end + end + + private def each_event(&) + open_trace_file do |input| + while line = input.gets(chomp: true) + if event = Parser.parse_event(line) + yield event + elsif @path != "-" + @stderr.print "WARN: invalid trace '" + @stderr.print line + @stderr.print "'\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 diff --git a/src/concurrent.cr b/src/concurrent.cr index af2f0aecf736..9df66306bb1d 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=%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/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/scheduler.cr b/src/crystal/scheduler.cr index c86d04309b14..47e470c9f50c 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=%p [%s]", fiber.as(Void*), fiber.name || "?" 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, "duration=%lld", time.total_nanoseconds.to_i64! Thread.current.scheduler.sleep(time) end def self.yield : Nil + Crystal.trace :sched, :yield + # TODO: Fiber switching and libevent for wasm32 {% unless flag?(:wasm32) %} Thread.current.scheduler.sleep(0.seconds) @@ -109,6 +115,7 @@ class Crystal::Scheduler end protected def resume(fiber : Fiber) : Nil + Crystal.trace :sched, :resume, "fiber=%p [%s]", fiber.as(Void*), fiber.name || "?" 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/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/system/thread.cr b/src/crystal/system/thread.cr index e6627538112d..9b2a0e2ed5ca 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,6 +102,11 @@ class Thread Crystal::System::Thread.current_thread 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 Crystal::System::Thread.current_thread = current @@ -120,6 +127,11 @@ class Thread # :nodoc: getter scheduler : Crystal::Scheduler { Crystal::Scheduler.new(self) } + # :nodoc: + def scheduler? : Crystal::Scheduler? + @scheduler + end + protected def start Thread.threads.push(self) Thread.current = self 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/pthread.cr b/src/crystal/system/unix/pthread.cr index f96d0bbf75ba..4b357b04281c 100644 --- a/src/crystal/system/unix/pthread.cr +++ b/src/crystal/system/unix/pthread.cr @@ -55,6 +55,12 @@ module Crystal::System::Thread end end + def self.current_thread? : ::Thread? + if ptr = LibC.pthread_getspecific(@@current_key) + ptr.as(::Thread) + 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 +69,10 @@ module Crystal::System::Thread {% else %} @[ThreadLocal] class_property current_thread : ::Thread { ::Thread.new } + + def self.current_thread? : ::Thread? + @@current_thread + end {% end %} private def system_join : Exception? diff --git a/src/crystal/system/unix/time.cr b/src/crystal/system/unix/time.cr index f7963f32f83f..58ed5b60e7e1 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/thread.cr b/src/crystal/system/win32/thread.cr index 2b44f66c28ce..9507e332b422 100644 --- a/src/crystal/system/win32/thread.cr +++ b/src/crystal/system/win32/thread.cr @@ -47,6 +47,10 @@ module Crystal::System::Thread @[ThreadLocal] class_property current_thread : ::Thread { ::Thread.new } + def self.current_thread? : ::Thread? + @@current_thread + 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..ab087c424cbf 100644 --- a/src/crystal/system/win32/time.cr +++ b/src/crystal/system/win32/time.cr @@ -53,21 +53,24 @@ 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 + 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 - {ticks // @@performance_frequency, (ticks.remainder(@@performance_frequency) * NANOSECONDS_PER_SECOND / @@performance_frequency).to_i32} + def self.ticks : UInt64 + LibC.QueryPerformanceCounter(out ticks) + ticks.to_u64! &* (NANOSECONDS_PER_SECOND // performance_frequency) end def self.load_localtime : ::Time::Location? diff --git a/src/crystal/tracing.cr b/src/crystal/tracing.cr new file mode 100644 index 000000000000..de43a6dde369 --- /dev/null +++ b/src/crystal/tracing.cr @@ -0,0 +1,173 @@ +module Crystal + {% if flag?(:tracing) %} + # :nodoc: + module Tracing + # IO-like object with a fixed capacity but dynamic size within the + # buffer's capacity (i.e. `0 <= size <= N`). Stops writing to the internal + # buffer when capacity is reached; further writes are skipped. + struct BufferIO(N) + getter size : Int32 + + def initialize + @buf = uninitialized UInt8[N] + @size = 0 + end + + def write(bytes : Bytes) : Nil + pos = @size + remaining = N - pos + return if remaining == 0 + + n = bytes.size.clamp(..remaining) + bytes.to_unsafe.copy_to(@buf.to_unsafe + pos, n) + @size = pos + n + end + + def to_slice : Bytes + Bytes.new(@buf.to_unsafe, @size) + end + end + + @[Flags] + enum Section + Gc + Sched + end + + @@sections = Section::None + @@startup_tick = 0_u64 + + @[AlwaysInline] + def self.enabled?(section : Section) : Bool + @@sections.includes?(section) + end + + @[AlwaysInline] + def self.startup_tick : UInt64 + @@startup_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 + # anything is available and musn't allocate into the GC HEAP. + def self.init + @@sections = Section::None + @@startup_tick = ::Crystal::System::Time.ticks + + {% if flag?(:win32) %} + buf = uninitialized UInt16[256] + name = UInt16.static_array({% for chr in "CRYSTAL_TRACE".chars %}{{chr.ord}}, {% end %} 0) + len = LibC.GetEnvironmentVariableW(name, buf, buf.size) + debug = buf.to_slice[0...len] if len > 0 + {% else %} + if ptr = LibC.getenv("CRYSTAL_TRACE") + len = LibC.strlen(ptr) + debug = Slice.new(ptr, len) if len > 0 + end + {% end %} + + return unless debug + + each_token(debug) do |token| + \{% begin %} + case token + \{% for name in Section.constants %} + when \{{name.downcase.id.stringify}}.to_slice + @@sections |= Section::\{{name.id}} + \{% end %} + end + \{% end %} + end + end + + private def self.each_token(bytes, delim = ',', &) + while e = bytes.index(delim.ord) + yield bytes[0, e] + bytes = bytes[(e + 1)..] + end + yield bytes[0..] unless bytes.size == 0 + end + + # Formats and prints a log message to stderr. The generated message is + # limited to 512 bytes (PIPE_BUF) after which it will be truncated. Being + # below PIPE_BUF the message shall be written atomically to stderr, + # avoiding interleaved or smashed traces from multiple threads. + # + # Windows may not have the same guarantees but the buffering should limit + # these from happening. + def self.log(fmt : String, *args) : Nil + buf = BufferIO(512).new + Crystal::System.printf(fmt, *args) { |bytes| buf.write bytes } + Crystal::System.print_error(buf.to_slice) + end + end + + macro trace(section, operation, fmt = "", *args, &block) + if ::Crystal::Tracing.enabled?(\{{section}}) + %tick = ::Crystal::System::Time.ticks + %time = %tick - ::Crystal::Tracing.startup_tick + \{% if block %} + %ret = \{{yield}} + %duration = ::Crystal::System::Time.ticks - %tick + ::Crystal.trace_end(%time, %duration, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}}) + %ret + \{% else %} + ::Crystal.trace_end(%time, nil, \{{section}}, \{{operation}}, \{{fmt}}, \{{args.splat}}) + nil + \{% end %} + else + \{{yield}} + end + end + + # :nodoc: + macro trace_end(time, duration, section, operation, fmt = "", *args) + {% 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}}) + {% else %} + {% thread_type = flag?(:linux) ? "0x%lx".id : "%p".id %} + + # 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?) && (%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 + %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 + {% else %} + # :nodoc: + module Tracing + def self.init + end + + def self.enabled?(section) + false + end + + def self.log(fmt : String, *args) + end + end + + macro trace(section, operation, fmt = "", *args, &block) + \{{yield}} + end + + # :nodoc: + 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 29ae825adab1..7a0fee3b12a9 100644 --- a/src/gc/boehm.cr +++ b/src/gc/boehm.cr @@ -1,6 +1,7 @@ {% if flag?(:preview_mt) %} require "crystal/rw_lock" {% end %} +require "crystal/tracing" # MUSL: On musl systems, libpthread is empty. The entire library is already included in libc. # The empty library is only available for POSIX compatibility. We don't need to link it. @@ -113,7 +114,32 @@ lib LibGC $stackbottom = GC_stackbottom : Void* {% end %} - fun set_on_collection_event = GC_set_on_collection_event(cb : ->) + alias OnHeapResizeProc = Word -> + fun set_on_heap_resize = GC_set_on_heap_resize(OnHeapResizeProc) + fun get_on_heap_resize = GC_get_on_heap_resize : OnHeapResizeProc + + enum EventType + START # COLLECTION + MARK_START + MARK_END + RECLAIM_START + RECLAIM_END + END # COLLECTION + PRE_STOP_WORLD # STOPWORLD_BEGIN + POST_STOP_WORLD # STOPWORLD_END + PRE_START_WORLD # STARTWORLD_BEGIN + POST_START_WORLD # STARTWORLD_END + THREAD_SUSPENDED + THREAD_UNSUSPENDED + end + + alias OnCollectionEventProc = EventType -> + fun set_on_collection_event = GC_set_on_collection_event(cb : OnCollectionEventProc) + fun get_on_collection_event = GC_get_on_collection_event : OnCollectionEventProc + + alias OnThreadEventProc = EventType, Void* -> + fun set_on_thread_event = GC_set_on_thread_event(cb : OnThreadEventProc) + fun get_on_thread_event = GC_get_on_thread_event : OnThreadEventProc $gc_no = GC_gc_no : Word $bytes_found = GC_bytes_found : SignedWord @@ -144,17 +170,23 @@ module GC # :nodoc: def self.malloc(size : LibC::SizeT) : Void* - LibGC.malloc(size) + Crystal.trace :gc, :malloc, "size=%lu", 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=%lu 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=%lu", size do + LibGC.realloc(ptr, size) + end end def self.init : Nil @@ -166,6 +198,14 @@ module GC LibGC.set_start_callback ->do GC.lock_write end + + {% if flag?(:tracing) %} + if ::Crystal::Tracing.enabled?(:gc) + set_on_heap_resize_proc + set_on_collection_events_proc + end + {% end %} + # By default the GC warns on big allocations/reallocations. This # is of limited use and pollutes program output with warnings. LibGC.set_warn_proc ->(msg, v) do @@ -178,8 +218,53 @@ module GC end end + {% if flag?(:tracing) %} + @@on_heap_resize : LibGC::OnHeapResizeProc? + @@on_collection_event : LibGC::OnCollectionEventProc? + + @@collect_start = 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=%llu", 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) { + case event_type + when .start? + @@collect_start = Time.monotonic + when .mark_start? + @@mark_start = Time.monotonic + when .reclaim_start? + @@sweep_start = Time.monotonic + when .end? + duration = ::Time.monotonic - @@collect_start + Crystal.trace_end @@collect_start, duration, "gc", "collect" + when .mark_end? + duration = ::Time.monotonic - @@mark_start + Crystal.trace_end @@collect_start, duration, "gc", "collect:mark" + when .reclaim_end? + duration = ::Time.monotonic - @@sweep_start + Crystal.trace_end @@collect_start, duration, "gc", "collect:sweep" + end + @@on_collection_event.try(&.call(event_type)) + }) + end + {% end %} + def self.collect - LibGC.collect + Crystal.trace :gc, :collect do + LibGC.collect + end end def self.enable @@ -195,7 +280,9 @@ module GC end def self.free(pointer : Void*) : Nil - LibGC.free(pointer) + Crystal.trace :gc, :free do + LibGC.free(pointer) + end end def self.add_finalizer(object : Reference) : Nil diff --git a/src/gc/none.cr b/src/gc/none.cr index c71ab05ccd8d..92585a769cc8 100644 --- a/src/gc/none.cr +++ b/src/gc/none.cr @@ -1,6 +1,7 @@ {% if flag?(:win32) %} require "c/process" {% end %} +require "crystal/tracing" module GC def self.init @@ -8,16 +9,19 @@ module GC # :nodoc: def self.malloc(size : LibC::SizeT) : Void* + Crystal.trace :gc, :malloc, "size=%lu", size LibC.malloc(size) end # :nodoc: def self.malloc_atomic(size : LibC::SizeT) : Void* + 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 LibC.realloc(pointer, size) end @@ -31,6 +35,7 @@ module GC end def self.free(pointer : Void*) : Nil + Crystal.trace :gc, :free LibC.free(pointer) end