From 9b54ad3a00669b218c35942fe9deed1d3a975482 Mon Sep 17 00:00:00 2001 From: Samuel Williams Date: Fri, 8 Nov 2024 14:15:46 +1300 Subject: [PATCH] Replace `ASYNC_SCHEDULER_DEBUG` with `Console.debug`. --- lib/async/scheduler.rb | 9 +++---- releases.md | 55 +++++++++++++---------------------------- test/async/scheduler.rb | 38 ++++++++++++++++++++++++++++ 3 files changed, 58 insertions(+), 44 deletions(-) diff --git a/lib/async/scheduler.rb b/lib/async/scheduler.rb index 6ef599e..b6aba79 100644 --- a/lib/async/scheduler.rb +++ b/lib/async/scheduler.rb @@ -16,9 +16,6 @@ module Async # Handles scheduling of fibers. Implements the fiber scheduler interface. class Scheduler < Node - # Whether to enable debug output. - DEBUG = ENV.fetch("ASYNC_SCHEDULER_DEBUG", false) == "true" - # Raised when an operation is attempted on a closed scheduler. class ClosedError < RuntimeError # Create a new error. @@ -391,9 +388,9 @@ def stop end rescue Interrupt => interrupt Thread.handle_interrupt(::SignalException => :never) do - if DEBUG - $stderr.puts "Scheduler interrupted: #{interrupt.inspect}" - self.print_hierarchy($stderr) + Console.debug(self) do |buffer| + buffer.puts "Scheduler interrupted: #{interrupt.inspect}" + self.print_hierarchy(buffer) end self.stop diff --git a/releases.md b/releases.md index d41a5be..335d415 100644 --- a/releases.md +++ b/releases.md @@ -2,47 +2,26 @@ ## Unreleased -### Async::Scheduler Debug +### Async::Scheduler Debugging -Occasionally on issues, I encounter people asking for help and I need more information. Pressing Ctrl-C to exit a hung program is common, but it doesn't provide enough information to diagnose the problem. I've added a new environment variable, `ASYNC_SCHEDULER_DEBUG=true` which will print out the current state of the scheduler when you press Ctrl-C. +Occasionally on issues, I encounter people asking for help and I need more information. Pressing Ctrl-C to exit a hung program is common, but it usually doesn't provide enough information to diagnose the problem. Setting the `CONSOLE_LEVEL=debug` environment variable will now print additional information about the scheduler when you interrupt it, including a backtrace of the current tasks. ``` -> ASYNC_SCHEDULER_DEBUG=true bundle exec ruby ./test.rb -^CScheduler interrupted: Interrupt -# - # - → /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:187:in `transfer' - /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:187:in `block' - /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:209:in `kernel_sleep' - ./test.rb:4:in `sleep' - ./test.rb:4:in `sleepy' - ./test.rb:10:in `sleepy' - ./test.rb:10:in `sleepy' - ./test.rb:10:in `sleepy' - ./test.rb:14:in `block in
' - /home/samuel/Developer/socketry/async/lib/async/task.rb:197:in `block in run' - /home/samuel/Developer/socketry/async/lib/async/task.rb:420:in `block in schedule' - # - → /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:187:in `transfer' - /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:187:in `block' - /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:209:in `kernel_sleep' - ./test.rb:4:in `sleep' - ./test.rb:4:in `sleepy' - ./test.rb:10:in `sleepy' - ./test.rb:10:in `sleepy' - ./test.rb:7:in `block in sleepy' - /home/samuel/Developer/socketry/async/lib/async/task.rb:197:in `block in run' - /home/samuel/Developer/socketry/async/lib/async/task.rb:420:in `block in schedule' -/home/samuel/Developer/socketry/async/lib/async/scheduler.rb:319:in `select': Interrupt - from /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:319:in `run_once!' - from /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:355:in `run_once' - from /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:417:in `block in run' - from /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:388:in `block in run_loop' - from /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:385:in `handle_interrupt' - from /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:385:in `run_loop' - from /home/samuel/Developer/socketry/async/lib/async/scheduler.rb:416:in `run' - from /home/samuel/Developer/socketry/async/lib/kernel/async.rb:34:in `Async' - from ./test.rb:13:in `
' +> CONSOLE_LEVEL=debug bundle exec ruby ./test.rb +^C 0.0s debug: Async::Reactor [oid=0x974] [ec=0x988] [pid=9116] [2024-11-08 14:12:03 +1300] + | Scheduler interrupted: Interrupt + | # + | # + | → /Users/samuel/Developer/socketry/async/lib/async/scheduler.rb:185:in `transfer' + | /Users/samuel/Developer/socketry/async/lib/async/scheduler.rb:185:in `block' + | /Users/samuel/Developer/socketry/async/lib/async/scheduler.rb:207:in `kernel_sleep' + | /Users/samuel/Developer/socketry/async/test.rb:7:in `sleep' + | /Users/samuel/Developer/socketry/async/test.rb:7:in `sleepy' + | /Users/samuel/Developer/socketry/async/test.rb:12:in `block in ' + | /Users/samuel/Developer/socketry/async/lib/async/task.rb:197:in `block in run' + | /Users/samuel/Developer/socketry/async/lib/async/task.rb:420:in `block in schedule' +/Users/samuel/Developer/socketry/async/lib/async/scheduler.rb:317:in `select': Interrupt +... (backtrace continues) ... ``` This gives better visibility into what the scheduler is doing, and should help diagnose issues. diff --git a/test/async/scheduler.rb b/test/async/scheduler.rb index 1bca6dc..b4df3f2 100644 --- a/test/async/scheduler.rb +++ b/test/async/scheduler.rb @@ -8,7 +8,11 @@ require "async/barrier" require "net/http" +require "sus/fixtures/console" + describe Async::Scheduler do + include_context Sus::Fixtures::Console::CapturedLogger + it "is supported" do expect(Async::Scheduler).to be(:supported?) end @@ -209,4 +213,38 @@ expect(child_task).not.to be(:transient?) end end + + it "prints out the stack trace of the scheduler" do + ready = Thread::Queue.new + thread = Thread.current + + scheduler = Async::Scheduler.new + + # This will interrupt the scheduler once it's running: + Thread.new do + ready.pop + thread.raise(Interrupt) + end + + expect do + begin + Fiber.set_scheduler(scheduler) + + scheduler.run do + while true + sleep(0) + ready.push(true) + end + end + ensure + Fiber.set_scheduler(nil) + end + end.to raise_exception(Interrupt) + + expect_console.to have_logged( + severity: be == :debug, + subject: be == scheduler, + message: be =~ /Scheduler interrupted/, + ) + end end