diff --git a/winit-appkit/src/event_loop.rs b/winit-appkit/src/event_loop.rs index 8455cd1da..d21086c7f 100644 --- a/winit-appkit/src/event_loop.rs +++ b/winit-appkit/src/event_loop.rs @@ -12,7 +12,7 @@ use objc2_app_kit::{ use objc2_core_foundation::{CFIndex, CFRunLoopActivity, kCFRunLoopCommonModes}; use objc2_foundation::{NSNotificationCenter, NSObjectProtocol}; use rwh_06::HasDisplayHandle; -use winit_common::core_foundation::{MainRunLoop, MainRunLoopObserver}; +use winit_common::core_foundation::{MainRunLoop, MainRunLoopObserver, tracing_observers}; use winit_core::application::ApplicationHandler; use winit_core::cursor::{CustomCursor as CoreCustomCursor, CustomCursorSource}; use winit_core::error::{EventLoopError, RequestError}; @@ -152,6 +152,7 @@ pub struct EventLoop { _did_finish_launching_observer: Retained>, _will_terminate_observer: Retained>, + _tracing_observers: Option<(MainRunLoopObserver, MainRunLoopObserver)>, _before_waiting_observer: MainRunLoopObserver, _after_waiting_observer: MainRunLoopObserver, } @@ -224,14 +225,20 @@ impl EventLoop { let main_loop = MainRunLoop::get(mtm); let mode = unsafe { kCFRunLoopCommonModes }.unwrap(); + // Tracing observers have the lowest and highest orderings. + let _tracing_observers = tracing_observers(mtm).inspect(|(start, end)| { + main_loop.add_observer(start, mode); + main_loop.add_observer(end, mode); + }); + let app_state_clone = Rc::clone(&app_state); let _before_waiting_observer = MainRunLoopObserver::new( mtm, CFRunLoopActivity::BeforeWaiting, true, - // Queued with the lowest priority to ensure it is processed after other observers. - // Without that, we'd get a `LoopExiting` after `AboutToWait`. - CFIndex::MAX, + // Queued with the second-lowest priority (tracing observers use the lowest) to ensure + // it is processed after other observers. + CFIndex::MAX - 1, move |_| app_state_clone.cleared(), ); main_loop.add_observer(&_before_waiting_observer, mode); @@ -241,8 +248,9 @@ impl EventLoop { mtm, CFRunLoopActivity::AfterWaiting, true, - // Queued with the highest priority to ensure it is processed before other observers. - CFIndex::MIN, + // Queued with the second-highest priority (tracing observers use the highest) to + // ensure it is processed before other observers. + CFIndex::MIN + 1, move |_| app_state_clone.wakeup(), ); main_loop.add_observer(&_after_waiting_observer, mode); @@ -253,6 +261,7 @@ impl EventLoop { window_target: ActiveEventLoop { app_state, mtm }, _did_finish_launching_observer, _will_terminate_observer, + _tracing_observers, _before_waiting_observer, _after_waiting_observer, }) diff --git a/winit-common/src/core_foundation/mod.rs b/winit-common/src/core_foundation/mod.rs index 09c10bf9d..8296c149a 100644 --- a/winit-common/src/core_foundation/mod.rs +++ b/winit-common/src/core_foundation/mod.rs @@ -6,7 +6,9 @@ mod event_loop_proxy; mod main_run_loop; mod main_run_loop_observer; +mod tracing_observers; pub use self::event_loop_proxy::*; pub use self::main_run_loop::*; pub use self::main_run_loop_observer::*; +pub use self::tracing_observers::*; diff --git a/winit-common/src/core_foundation/tracing_observers.rs b/winit-common/src/core_foundation/tracing_observers.rs new file mode 100644 index 000000000..63d0d4a86 --- /dev/null +++ b/winit-common/src/core_foundation/tracing_observers.rs @@ -0,0 +1,146 @@ +use std::cell::RefCell; +use std::rc::Rc; + +use objc2::MainThreadMarker; +use objc2_core_foundation::{CFIndex, CFRunLoop, CFRunLoopActivity, kCFRunLoopDefaultMode}; +use tracing::span::EnteredSpan; +use tracing::{Level, error, field, span_enabled, trace_span}; + +use crate::core_foundation::MainRunLoopObserver; + +/// Create two run loop observers that add TRACE-level [spans][tracing::span]. +/// +/// This is useful when debugging run loops, it makes it easier to see in which run loop activity an +/// event is triggered inside (if any). +/// +/// When debugging these interactions, it can also be useful to configure your tracing subscriber +/// with `.with_span_events(tracing_subscriber::fmt::format::FmtSpan::ACTIVE)` to emit events upon +/// entering and exiting these stages. +pub fn tracing_observers( + mtm: MainThreadMarker, +) -> Option<(MainRunLoopObserver, MainRunLoopObserver)> { + // Observers are a bit costly, so don't create them if the tracing-level for this module is + // configured to disable them. + if !span_enabled!(Level::TRACE) { + return None; + } + + /// The state that we think the runloop is currently in. + /// + /// The order of activities we observe if waiting twice looks something like: + /// - CFRunLoopActivity::Entry + /// - CFRunLoopActivity::BeforeTimers + /// - CFRunLoopActivity::BeforeSources + /// - CFRunLoopActivity::BeforeWaiting + /// - CFRunLoopActivity::AfterWaiting + /// - CFRunLoopActivity::BeforeTimers + /// - CFRunLoopActivity::BeforeSources + /// - CFRunLoopActivity::BeforeWaiting + /// - CFRunLoopActivity::AfterWaiting + /// - CFRunLoopActivity::Exit + /// + /// And if not waiting, it looks something like: + /// - CFRunLoopActivity::Entry + /// - CFRunLoopActivity::BeforeTimers + /// - CFRunLoopActivity::BeforeSources + /// - CFRunLoopActivity::Exit + #[derive(Default)] + #[allow(unused)] // EnteredSpans are kept around + enum RunLoopState { + /// Currently processing `Entry`/`Exit` observers. + #[default] + Entered, + /// Currently processing timers or `BeforeTimers` observers. + Timers(EnteredSpan), + /// Currently processing sources or `BeforeSources` observers. + Sources(EnteredSpan), + /// Currently waiting or processing `BeforeWaiting`/`AfterWaiting` observers. + Waiting(EnteredSpan), + } + + // A list of currently entered (outer) spans and their state. + // + // This is a list because runloops can be run recursively. + let spans: Rc>> = Rc::new(RefCell::new(Vec::new())); + let spans_clone = Rc::clone(&spans); + + // An observer at the start of run loop activities. + let activities = CFRunLoopActivity::Entry + | CFRunLoopActivity::BeforeTimers + | CFRunLoopActivity::BeforeSources + | CFRunLoopActivity::BeforeWaiting; + let start = MainRunLoopObserver::new(mtm, activities, true, CFIndex::MIN, move |activity| { + match activity { + // Add an outer span for each runloop iteration. + CFRunLoopActivity::Entry => { + let span = trace_span!("inside runloop", mode = field::Empty); + + // Get the mode dynamically, the observer may added to multiple different modes. + let mode = CFRunLoop::current().unwrap().current_mode().unwrap(); + // Mode isn't interesting if it's the default mode. + if &*mode != unsafe { kCFRunLoopDefaultMode }.unwrap() { + span.record("mode", field::display(mode)); + } + + let entered = span.entered(); + spans.borrow_mut().push((entered, RunLoopState::Entered)); + }, + + // Add inner spans that help inspecting the state the runloop is in. + CFRunLoopActivity::BeforeTimers => { + if let Some((_, state)) = spans.borrow_mut().last_mut() { + *state = RunLoopState::Entered; // Drop any previous spans. + *state = RunLoopState::Timers(trace_span!("processing timers").entered()); + } else { + error!("unbalanced observer invocations"); + } + }, + CFRunLoopActivity::BeforeSources => { + if let Some((_, state)) = spans.borrow_mut().last_mut() { + *state = RunLoopState::Entered; // Drop any previous spans. + *state = RunLoopState::Sources(trace_span!("processing sources").entered()); + } else { + error!("unbalanced observer invocations"); + } + }, + CFRunLoopActivity::BeforeWaiting => { + if let Some((_, state)) = spans.borrow_mut().last_mut() { + *state = RunLoopState::Entered; // Drop any previous spans. + *state = RunLoopState::Waiting(trace_span!("waiting").entered()); + } else { + error!("unbalanced observer invocations"); + } + }, + + activity => unreachable!("unexpected activity: {activity:?}"), + } + }); + + // An observer at the end of run loop activities. + let activities = CFRunLoopActivity::AfterWaiting | CFRunLoopActivity::Exit; + let end = MainRunLoopObserver::new(mtm, activities, true, CFIndex::MAX, move |activity| { + match activity { + CFRunLoopActivity::AfterWaiting => { + if let Some((_, state)) = spans_clone.borrow_mut().last_mut() { + // Transition from the waiting state to the initial state. + *state = RunLoopState::Entered; + } else { + error!("unbalanced observer invocations"); + } + }, + + CFRunLoopActivity::Exit => { + if let Some((span, state)) = spans_clone.borrow_mut().pop() { + drop(state); // Explicitly exit and drop inner span. + drop(span); // Explicitly exit and drop outer span. + } else { + error!("unbalanced observer invocations"); + } + }, + + activity => unreachable!("unexpected activity: {activity:?}"), + } + }); + + Some((start, end)) +} diff --git a/winit-uikit/src/event_loop.rs b/winit-uikit/src/event_loop.rs index d9e864b08..c98046ae3 100644 --- a/winit-uikit/src/event_loop.rs +++ b/winit-uikit/src/event_loop.rs @@ -12,7 +12,7 @@ use objc2_ui_kit::{ UIApplicationWillResignActiveNotification, UIApplicationWillTerminateNotification, UIScreen, }; use rwh_06::HasDisplayHandle; -use winit_common::core_foundation::{MainRunLoop, MainRunLoopObserver}; +use winit_common::core_foundation::{MainRunLoop, MainRunLoopObserver, tracing_observers}; use winit_core::application::ApplicationHandler; use winit_core::cursor::{CustomCursor, CustomCursorSource}; use winit_core::error::{EventLoopError, NotSupportedError, RequestError}; @@ -134,6 +134,7 @@ pub struct EventLoop { _will_terminate_observer: Retained>, _did_receive_memory_warning_observer: Retained>, + _tracing_observers: Option<(MainRunLoopObserver, MainRunLoopObserver)>, _wakeup_observer: MainRunLoopObserver, _main_events_cleared_observer: MainRunLoopObserver, _events_cleared_observer: MainRunLoopObserver, @@ -226,12 +227,19 @@ impl EventLoop { let main_loop = MainRunLoop::get(mtm); let mode = unsafe { kCFRunLoopDefaultMode }.unwrap(); + // Tracing observers have the lowest and highest orderings. + let _tracing_observers = tracing_observers(mtm).inspect(|(start, end)| { + main_loop.add_observer(start, mode); + main_loop.add_observer(end, mode); + }); + let _wakeup_observer = MainRunLoopObserver::new( mtm, CFRunLoopActivity::AfterWaiting, true, - // Queued with the highest priority to ensure it is processed before other observers. - CFIndex::MIN, + // Queued with the second-highest priority (tracing observers use the highest) to + // ensure it is processed before other observers. + CFIndex::MIN + 1, move |_| app_state::handle_wakeup_transition(mtm), ); main_loop.add_observer(&_wakeup_observer, mode); @@ -241,17 +249,17 @@ impl EventLoop { CFRunLoopActivity::BeforeWaiting, true, // Core Animation registers its `CFRunLoopObserver` that performs drawing operations in - // `CA::Transaction::ensure_implicit` with a priority of `0x1e8480`. We set the + // `CA::Transaction::ensure_implicit` with a priority of `2000000`. We set the // main_end priority to be 0, in order to send `AboutToWait` before `RedrawRequested`. // This value was chosen conservatively to guard against apple using different // priorities for their redraw observers in different OS's or on different devices. If // it so happens that it's too conservative, the main symptom would be non-redraw // events coming in after `AboutToWait`. // - // The value of `0x1e8480` was determined by inspecting stack traces and the associated + // The value of `2000000` was determined by inspecting stack traces and the associated // registers for every `CFRunLoopAddObserver` call on an iPad Air 2 running iOS 11.4. // - // Also tested to be `0x1e8480` on iPhone 8, iOS 13 beta 4. + // Also tested to be `2000000` on iPhone 8, iOS 13 beta 4. 0, move |_| app_state::handle_main_events_cleared(mtm), ); @@ -261,8 +269,9 @@ impl EventLoop { mtm, CFRunLoopActivity::BeforeWaiting, true, - // Queued with the lowest priority to ensure it is processed after other observers. - CFIndex::MAX, + // Queued with the second-lowest priority (tracing observers use the lowest) to ensure + // it is processed after other observers. + CFIndex::MAX - 1, move |_| app_state::handle_events_cleared(mtm), ); main_loop.add_observer(&_events_cleared_observer, mode); @@ -277,6 +286,7 @@ impl EventLoop { _did_enter_background_observer, _will_terminate_observer, _did_receive_memory_warning_observer, + _tracing_observers, _wakeup_observer, _main_events_cleared_observer, _events_cleared_observer,