Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Crystal::Tracing for runtime tracing #14659

Merged
merged 19 commits into from
Jun 15, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
19 commits
Select commit Hold shift + click to select a range
b55d66c
Add Crystal::System::Thread.current_thread? + Thread#scheduler?
ysbaddaden May 27, 2024
824e2af
Initial Crystal.trace implementation
ysbaddaden May 27, 2024
eddc005
Line protocol with abstract metadata (named tuple)
ysbaddaden May 27, 2024
22f5aac
Trace: print to file (CRYSTAL_TRACE_FILE)
ysbaddaden May 27, 2024
d28e6ce
Fix: Crystal::Tracing.init shall return nil
ysbaddaden Jun 3, 2024
149f3d4
Prefer System.printf_error over LibC.dprintf
ysbaddaden Jun 4, 2024
c8fd378
Fix: no need to prefix the Crystal namespace
ysbaddaden Jun 4, 2024
cbb904f
Fix: remove unused @@startup_tick
ysbaddaden Jun 4, 2024
379b4a5
fixup! Trace: print to file (CRYSTAL_TRACE_FILE)
ysbaddaden Jun 4, 2024
a54c848
Merge branch 'master' into feature/tracing
straight-shoota Jun 6, 2024
5541f6e
Fix: leverage String.each_utf16_char instead of external C call
ysbaddaden Jun 13, 2024
11faaa3
Apply code review suggestion
ysbaddaden Jun 13, 2024
d214022
Replace macro with a couple methods
ysbaddaden Jun 13, 2024
9a9025c
fixup! Fix: leverage String.each_utf16_char instead of external C call
ysbaddaden Jun 13, 2024
9ce8adb
fixup! Replace macro with a couple methods
ysbaddaden Jun 13, 2024
34ee68d
Fix: don't overload Enum#to_s (use distinct method)
ysbaddaden Jun 13, 2024
e8648ef
Fix: use Pointer::Appender in print_error(Slice(UInt8))
ysbaddaden Jun 13, 2024
5b65aad
Fix: use ensure instead of tap so we still print the trace
ysbaddaden Jun 13, 2024
1dfe3c5
Refactor: Section.from_id(slice) and Section#to_id
ysbaddaden Jun 13, 2024
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions src/concurrent.cr
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
require "fiber"
require "channel"
require "crystal/scheduler"
require "crystal/tracing"

# Blocks the current fiber for the specified number of seconds.
#
Expand Down Expand Up @@ -59,6 +60,7 @@ end
# ```
def spawn(*, name : String? = nil, same_thread = false, &block)
fiber = Fiber.new(name, &block)
Crystal.trace :sched, "spawn", fiber: fiber
{% if flag?(:preview_mt) %} fiber.set_current_thread if same_thread {% end %}
fiber.enqueue
fiber
Expand Down
1 change: 1 addition & 0 deletions src/crystal/main.cr
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,7 @@ module Crystal
# same can be accomplished with `at_exit`. But in some cases
# redefinition of C's main is needed.
def self.main(&block)
{% if flag?(:tracing) %} Crystal::Tracing.init {% end %}
GC.init

status =
Expand Down
39 changes: 25 additions & 14 deletions src/crystal/scheduler.cr
Original file line number Diff line number Diff line change
Expand Up @@ -25,21 +25,23 @@ class Crystal::Scheduler
end

def self.enqueue(fiber : Fiber) : Nil
thread = Thread.current
scheduler = thread.scheduler
Crystal.trace :sched, "enqueue", fiber: fiber do
thread = Thread.current
scheduler = thread.scheduler

{% if flag?(:preview_mt) %}
th = fiber.get_current_thread
th ||= fiber.set_current_thread(scheduler.find_target_thread)
{% if flag?(:preview_mt) %}
th = fiber.get_current_thread
th ||= fiber.set_current_thread(scheduler.find_target_thread)

if th == thread
if th == thread
scheduler.enqueue(fiber)
else
th.scheduler.send_fiber(fiber)
end
{% else %}
scheduler.enqueue(fiber)
else
th.scheduler.send_fiber(fiber)
end
{% else %}
scheduler.enqueue(fiber)
{% end %}
{% end %}
end
end

def self.enqueue(fibers : Enumerable(Fiber)) : Nil
Expand All @@ -49,6 +51,7 @@ class Crystal::Scheduler
end

def self.reschedule : Nil
Crystal.trace :sched, "reschedule"
Thread.current.scheduler.reschedule
end

Expand All @@ -58,10 +61,13 @@ class Crystal::Scheduler
end

def self.sleep(time : Time::Span) : Nil
Crystal.trace :sched, "sleep", for: time.total_nanoseconds.to_i64!
Thread.current.scheduler.sleep(time)
end

def self.yield : Nil
Crystal.trace :sched, "yield"

# TODO: Fiber switching and libevent for wasm32
{% unless flag?(:wasm32) %}
Thread.current.scheduler.sleep(0.seconds)
Expand Down Expand Up @@ -109,6 +115,7 @@ class Crystal::Scheduler
end

protected def resume(fiber : Fiber) : Nil
Crystal.trace :sched, "resume", fiber: fiber
validate_resumable(fiber)

{% if flag?(:preview_mt) %}
Expand Down Expand Up @@ -149,7 +156,9 @@ class Crystal::Scheduler
resume(runnable) unless runnable == @thread.current_fiber
break
else
@event_loop.run(blocking: true)
Crystal.trace :sched, "event_loop" do
@event_loop.run(blocking: true)
end
end
end
end
Expand Down Expand Up @@ -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
Expand Down
33 changes: 32 additions & 1 deletion src/crystal/system/print_error.cr
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,37 @@ module Crystal::System
{% end %}
end

# Print a UTF-16 slice as UTF-8 directly to stderr. Useful on Windows to print
# strings returned from the unicode variant of the Win32 API.
def self.print_error(bytes : Slice(UInt16)) : Nil
utf8 = uninitialized UInt8[512]
appender = utf8.to_unsafe.appender

String.each_utf16_char(bytes) do |char|
if appender.size > utf8.size - char.bytesize
# buffer is full (char won't fit)
print_error utf8.to_slice[0...appender.size]
appender = utf8.to_unsafe.appender
end

char.each_byte do |byte|
appender << byte
end
end

if appender.size > 0
print_error utf8.to_slice[0...appender.size]
end
end

def self.print(handle : FileDescriptor::Handle, bytes : Bytes) : Nil
{% if flag?(:unix) || flag?(:wasm32) %}
LibC.write handle, bytes, bytes.size
{% elsif flag?(:win32) %}
LibC.WriteFile(Pointer(FileDescriptor::Handle).new(handle), bytes, bytes.size, out _, nil)
{% end %}
end

# Minimal drop-in replacement for C `printf` function. Yields successive
# non-empty `Bytes` to the block, which should do the actual printing.
#
Expand Down Expand Up @@ -109,7 +140,7 @@ module Crystal::System
end

# simplified version of `Int#internal_to_s`
private def self.to_int_slice(num, base, signed, width, &)
protected def self.to_int_slice(num, base, signed, width, &)
if num == 0
yield "0".to_slice
return
Expand Down
Loading
Loading