Apple: Trace CFRunLoop activities

Add two run loop observers that:
- Create a TRACE-level span when the run loop enters a new state.
- Drops the span when the run loop exits that state.

These spans attach information to events, such that e.g. resizing a view
produces messages like:
```
TRACE inside runloop{mode=NSEventTrackingRunLoopMode}:timers:
  winit_appkit::util: Triggered `drawRect:` target="winit_appkit::view"
TRACE inside runloop{mode=NSEventTrackingRunLoopMode}:timers:
  winit_appkit::util: Completed `drawRect:` target="winit_appkit::view"
```

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<ProtocolObject<dyn NSObjectProtocol>>,
     _will_terminate_observer: Retained<ProtocolObject<dyn NSObjectProtocol>>,
 
+    _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,
         })

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::*;

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<RefCell<Vec<(EnteredSpan, RunLoopState)>>> = 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))
+}

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<ProtocolObject<dyn NSObjectProtocol>>,
     _did_receive_memory_warning_observer: Retained<ProtocolObject<dyn NSObjectProtocol>>,
 
+    _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,