Add support for logging operations to debug selector.

guides/getting-started/readme.md

@@ -49,3 +49,13 @@ selector.select(1)
 # Results in:
 # {:read=>"Hello World"}
 ```
+
+## Debugging
+
+The {ruby IO::Event::Debug::Selector} class adds extra validations and checks at the expense of performance. It can also log all operations. You can use this by setting the following environment variables:
+
+```shell
+$ IO_EVENT_SELECTOR_DEBUG=y IO_EVENT_SELECTOR_DEBUG_LOG=/dev/stderr bundle exec ./my_script.rb
+```
+
+The format of the log is subject to change, but it may be useful for debugging.

lib/io/event/debug/selector.rb

@@ -9,7 +9,17 @@ module IO::Event
 	module Debug
 		# Enforces the selector interface and delegates operations to a wrapped selector instance.
 		class Selector
-			def initialize(selector)
+			def self.wrap(selector, env = ENV)
+				log = nil
+
+				if log_path = env['IO_EVENT_DEBUG_SELECTOR_LOG']
+					log = File.open(log_path, 'w')
+				end
+
+				return self.new(selector, log: log)
+			end
+
+			def initialize(selector, log: nil)
 				@selector = selector
 
 				@readable = {}
@@ -19,13 +29,29 @@ def initialize(selector)
 				unless Fiber.current == selector.loop
 					Kernel::raise "Selector must be initialized on event loop fiber!"
 				end
+
+				@log = log
+			end
+
+			def now
+				Process.clock_gettime(Process::CLOCK_MONOTONIC)
+			end
+
+			def log(message)
+				return unless @log
+
+				Fiber.blocking do
+					@log.puts("T+%10.1f; %s" % [now, message])
+				end
 			end
 
 			def wakeup
 				@selector.wakeup
 			end
 
 			def close
+				log("Closing selector")
+
 				if @selector.nil?
 					Kernel::raise "Selector already closed!"
 				end
@@ -36,22 +62,27 @@ def close
 
 			# Transfer from the calling fiber to the event loop.
 			def transfer
+				log("Transfering to event loop")
 				@selector.transfer
 			end
 
 			def resume(*arguments)
+				log("Resuming fiber with #{arguments.inspect}")
 				@selector.resume(*arguments)
 			end
 
 			def yield
+				log("Yielding to event loop")
 				@selector.yield
 			end
 
 			def push(fiber)
+				log("Pushing fiber #{fiber.inspect} to ready list")
 				@selector.push(fiber)
 			end
 
 			def raise(fiber, *arguments)
+				log("Raising exception on fiber #{fiber.inspect} with #{arguments.inspect}")
 				@selector.raise(fiber, *arguments)
 			end
 
@@ -60,26 +91,31 @@ def ready?
 			end
 
 			def process_wait(*arguments)
+				log("Waiting for process with #{arguments.inspect}")
 				@selector.process_wait(*arguments)
 			end
 
 			def io_wait(fiber, io, events)
+				log("Waiting for IO #{io.inspect} for events #{events.inspect}")
 				@selector.io_wait(fiber, io, events)
 			end
 
-			def io_read(...)
-				@selector.io_read(...)
+			def io_read(fiber, io, buffer, length, offset = 0)
+				log("Reading from IO #{io.inspect} with buffer #{buffer}; length #{length} offset #{offset}")
+				@selector.io_read(fiber, io, buffer, length, offset)
 			end
 
-			def io_write(...)
-				@selector.io_write(...)
+			def io_write(fiber, io, buffer, length, offset = 0)
+				log("Writing to IO #{io.inspect} with buffer #{buffer}; length #{length} offset #{offset}")
+				@selector.io_write(fiber, io, buffer, length, offset)
 			end
 
 			def respond_to?(name, include_private = false)
 				@selector.respond_to?(name, include_private)
 			end
 
 			def select(duration = nil)
+				log("Selecting for #{duration.inspect}")
 				unless Fiber.current == @selector.loop
 					Kernel::raise "Selector must be run on event loop fiber!"
 				end

lib/io/event/selector.rb

@@ -29,7 +29,7 @@ def self.new(loop, env = ENV)
 			selector = default(env).new(loop)
 
 			if debug = env['IO_EVENT_DEBUG_SELECTOR']
-				selector = Debug::Selector.new(selector)
+				selector = Debug::Selector.wrap(selector, env)
 			end
 
 			return selector