dnrops
/
xilem
mirror of https://github.com/linebender/xilem
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Refactor tracing handling for events (#688) 

Inspired by #687, I thought some more tidying up of the log file was in
order.

The main differences are:
1) Higher-scale spans exist for key operations
2) Something is always logged for each event, but less for high-density
eventskey
3) Less is logged for high-density events
4) Key repeats are no longer treated as high density
5) We no longer do extra work if the hover and focus paths haven't
changed (which also means less logging)

This PR *does not* depend on #687
This commit is contained in:
Daniel McNab 2024-10-21 14:11:24 +01:00 committed by GitHub
parent 6f111233d7
commit 03245d0080
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
6 changed files with 155 additions and 107 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
masonry/src/event.rs
View File

@ -384,6 +384,7 @@ impl PointerEvent {
impl TextEvent {
pub fn short_name(&self) -> &'static str {
match self {
TextEvent::KeyboardKey(KeyEvent { repeat: true, .. }, _) => "KeyboardKey (repeat)",
TextEvent::KeyboardKey(_, _) => "KeyboardKey",
TextEvent::Ime(Ime::Disabled) => "Ime::Disabled",
TextEvent::Ime(Ime::Enabled) => "Ime::Enabled",
@ -397,7 +398,7 @@ impl TextEvent {
pub fn is_high_density(&self) -> bool {
match self {
TextEvent::KeyboardKey(event, _) => event.repeat,
TextEvent::KeyboardKey(_, _) => false,
TextEvent::Ime(_) => false,
// Basically every mouse click/scroll event seems to produce a modifier change event.
TextEvent::ModifierChange(_) => true,

3
masonry/src/event_loop_runner.rs
View File

@ -5,7 +5,7 @@ use std::num::NonZeroUsize;
use std::sync::Arc;
use accesskit_winit::Adapter;
use tracing::{debug, warn};
use tracing::{debug, info_span, warn};
use vello::kurbo::Affine;
use vello::peniko::Color;
use vello::util::{RenderContext, RenderSurface};
@ -458,6 +458,7 @@ impl MasonryState<'_> {
.handle_window_event(WindowEvent::Rescale(scale_factor));
}
WinitWindowEvent::RedrawRequested => {
let _span = info_span!("redraw");
self.render_root.handle_window_event(WindowEvent::AnimFrame);
let (scene, tree_update) = self.render_root.redraw();
self.render(scene);

61
masonry/src/passes/event.rs
View File

@ -37,6 +37,7 @@ fn run_event_pass<E>(
event: &E,
allow_pointer_capture: bool,
pass_fn: impl FnMut(&mut dyn Widget, &mut EventCtx, &E),
trace: bool,
) -> Handled {
let mut pass_fn = pass_fn;
@ -59,11 +60,14 @@ fn run_event_pass<E>(
let widget = widget_mut.item;
if !is_handled {
trace!(
"Widget '{}' {} visited",
widget.short_type_name(),
widget_id,
);
let _span = widget.make_trace_span().entered();
if trace {
trace!(
"Widget '{}' {} visited",
widget.short_type_name(),
widget_id,
);
}
pass_fn(widget, &mut ctx, event);
is_handled = ctx.is_handled;
@ -78,8 +82,14 @@ fn run_event_pass<E>(
// --- MARK: POINTER_EVENT ---
pub(crate) fn run_on_pointer_event_pass(root: &mut RenderRoot, event: &PointerEvent) -> Handled {
let _span = info_span!("pointer_event").entered();
if !event.is_high_density() {
let _span = info_span!("dispatch_pointer_event").entered();
if event.is_high_density() {
// We still want to record that this pass occurred in the debug file log.
// However, we choose not record any other tracing for this event,
// as that would have a lot of noise.
trace!("Running ON_POINTER_EVENT pass with {}", event.short_name());
} else {
debug!("Running ON_POINTER_EVENT pass with {}", event.short_name());
}
@ -98,6 +108,7 @@ pub(crate) fn run_on_pointer_event_pass(root: &mut RenderRoot, event: &PointerEv
|widget, ctx, event| {
widget.on_pointer_event(ctx, event);
},
!event.is_high_density(),
);
if matches!(
@ -132,16 +143,29 @@ pub(crate) fn run_on_text_event_pass(root: &mut RenderRoot, event: &TextEvent) -
run_on_pointer_event_pass(root, &PointerEvent::new_pointer_leave());
}
let _span = info_span!("text_event").entered();
if !event.is_high_density() {
let _span = info_span!("dispatch_text_event").entered();
if event.is_high_density() {
// We still want to record that this pass occurred in the debug file log.
// However, we choose not record any other tracing for this event,
// as that would have a lot of noise.
trace!("Running ON_TEXT_EVENT pass with {}", event.short_name());
} else {
debug!("Running ON_TEXT_EVENT pass with {}", event.short_name());
}
let target = root.global_state.focused_widget;
let mut handled = run_event_pass(root, target, event, false, |widget, ctx, event| {
widget.on_text_event(ctx, event);
});
let mut handled = run_event_pass(
root,
target,
event,
false,
|widget, ctx, event| {
widget.on_text_event(ctx, event);
},
!event.is_high_density(),
);
// Handle Tab focus
if let TextEvent::KeyboardKey(key, mods) = event {
@ -178,9 +202,16 @@ pub(crate) fn run_on_access_event_pass(
let _span = info_span!("access_event").entered();
debug!("Running ON_ACCESS_EVENT pass with {}", event.short_name());
let mut handled = run_event_pass(root, Some(target), event, false, |widget, ctx, event| {
widget.on_access_event(ctx, event);
});
let mut handled = run_event_pass(
root,
Some(target),
event,
false,
|widget, ctx, event| {
widget.on_access_event(ctx, event);
},
true,
);
// Handle focus events
match event.action {

189
masonry/src/passes/update.rs
View File

@ -387,6 +387,7 @@ pub(crate) fn run_update_focus_chain_pass(root: &mut RenderRoot) {
// --- MARK: UPDATE FOCUS ---
pub(crate) fn run_update_focus_pass(root: &mut RenderRoot) {
let _span = info_span!("update_focus").entered();
// If the focused widget is disabled, stashed or removed, we set
// the focused id to None
if let Some(id) = root.global_state.next_focused_widget {
@ -402,49 +403,53 @@ pub(crate) fn run_update_focus_pass(root: &mut RenderRoot) {
let prev_focused_path = std::mem::take(&mut root.global_state.focused_path);
let next_focused_path = get_id_path(root, next_focused);
let mut focused_set = HashSet::new();
for widget_id in &next_focused_path {
focused_set.insert(*widget_id);
}
trace!("prev_focused_path: {:?}", prev_focused_path);
trace!("next_focused_path: {:?}", next_focused_path);
// This is the same algorithm as the one in
// run_update_pointer_pass
// See comment in that function.
fn update_focused_status_of(
root: &mut RenderRoot,
widget_id: WidgetId,
focused_set: &HashSet<WidgetId>,
) {
run_targeted_update_pass(root, Some(widget_id), |widget, ctx| {
let has_focus = focused_set.contains(&ctx.widget_id());
if ctx.widget_state.has_focus != has_focus {
widget.update(ctx, &Update::ChildFocusChanged(has_focus));
}
ctx.widget_state.has_focus = has_focus;
});
}
// TODO - Make sure widgets are iterated from the bottom up.
// TODO - Document the iteration order for update_focus pass.
for widget_id in prev_focused_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.has_focus
!= focused_set.contains(&widget_id)
{
update_focused_status_of(root, widget_id, &focused_set);
// We don't just compare `prev_focused` and `next_focused` they could be the same widget
// but one of their ancestors could have been reparented.
if prev_focused_path != next_focused_path {
let mut focused_set = HashSet::new();
for widget_id in &next_focused_path {
focused_set.insert(*widget_id);
}
}
for widget_id in next_focused_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.has_focus
!= focused_set.contains(&widget_id)
{
update_focused_status_of(root, widget_id, &focused_set);
trace!("prev_focused_path: {:?}", prev_focused_path);
trace!("next_focused_path: {:?}", next_focused_path);
// This is the same algorithm as the one in
// run_update_pointer_pass
// See comment in that function.
fn update_focused_status_of(
root: &mut RenderRoot,
widget_id: WidgetId,
focused_set: &HashSet<WidgetId>,
) {
run_targeted_update_pass(root, Some(widget_id), |widget, ctx| {
let has_focus = focused_set.contains(&ctx.widget_id());
if ctx.widget_state.has_focus != has_focus {
widget.update(ctx, &Update::ChildFocusChanged(has_focus));
}
ctx.widget_state.has_focus = has_focus;
});
}
// TODO - Make sure widgets are iterated from the bottom up.
// TODO - Document the iteration order for update_focus pass.
for widget_id in prev_focused_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.has_focus
!= focused_set.contains(&widget_id)
{
update_focused_status_of(root, widget_id, &focused_set);
}
}
for widget_id in next_focused_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.has_focus
!= focused_set.contains(&widget_id)
{
update_focused_status_of(root, widget_id, &focused_set);
}
}
}
@ -524,6 +529,8 @@ pub(crate) fn run_update_pointer_pass(root: &mut RenderRoot) {
if !root.global_state.needs_pointer_pass {
return;
}
let _span = info_span!("update_pointer").entered();
root.global_state.needs_pointer_pass = false;
let pointer_pos = root.last_mouse_pos.map(|pos| (pos.x, pos.y).into());
@ -556,54 +563,58 @@ pub(crate) fn run_update_pointer_pass(root: &mut RenderRoot) {
let prev_hovered_path = std::mem::take(&mut root.global_state.hovered_path);
let next_hovered_path = get_id_path(root, next_hovered_widget);
let mut hovered_set = HashSet::new();
for widget_id in &next_hovered_path {
hovered_set.insert(*widget_id);
}
trace!("prev_hovered_path: {:?}", prev_hovered_path);
trace!("next_hovered_path: {:?}", next_hovered_path);
// This algorithm is written to be resilient to future changes like reparenting and multiple
// cursors. In theory it's O(Depth² * CursorCount) in the worst case, which isn't too bad
// (cursor count is usually 1 or 2, depth is usually small), but in practice it's virtually
// always O(Depth * CursorCount) because we only need to update the hovered status of the
// widgets that changed.
// The above assumes that accessing the widget tree is O(1) for simplicity.
fn update_hovered_status_of(
root: &mut RenderRoot,
widget_id: WidgetId,
hovered_set: &HashSet<WidgetId>,
) {
run_targeted_update_pass(root, Some(widget_id), |widget, ctx| {
let is_hovered = hovered_set.contains(&ctx.widget_id());
if ctx.widget_state.is_hovered != is_hovered {
widget.update(ctx, &Update::HoveredChanged(is_hovered));
ctx.widget_state.request_accessibility = true;
ctx.widget_state.needs_accessibility = true;
}
ctx.widget_state.is_hovered = is_hovered;
});
}
// TODO - Make sure widgets are iterated from the bottom up.
// TODO - Document the iteration order for update_pointer pass.
for widget_id in prev_hovered_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.is_hovered
!= hovered_set.contains(&widget_id)
{
update_hovered_status_of(root, widget_id, &hovered_set);
// We don't just compare `prev_focused` and `next_focused` they could be the same widget
// but one of their ancestors could have been reparented.
if prev_hovered_path != next_hovered_path {
let mut hovered_set = HashSet::new();
for widget_id in &next_hovered_path {
hovered_set.insert(*widget_id);
}
}
for widget_id in next_hovered_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.is_hovered
!= hovered_set.contains(&widget_id)
{
update_hovered_status_of(root, widget_id, &hovered_set);
trace!("prev_hovered_path: {:?}", prev_hovered_path);
trace!("next_hovered_path: {:?}", next_hovered_path);
// This algorithm is written to be resilient to future changes like reparenting and multiple
// cursors. In theory it's O(Depth² * CursorCount) in the worst case, which isn't too bad
// (cursor count is usually 1 or 2, depth is usually small), but in practice it's virtually
// always O(Depth * CursorCount) because we only need to update the hovered status of the
// widgets that changed.
// The above assumes that accessing the widget tree is O(1) for simplicity.
fn update_hovered_status_of(
root: &mut RenderRoot,
widget_id: WidgetId,
hovered_set: &HashSet<WidgetId>,
) {
run_targeted_update_pass(root, Some(widget_id), |widget, ctx| {
let is_hovered = hovered_set.contains(&ctx.widget_id());
if ctx.widget_state.is_hovered != is_hovered {
widget.update(ctx, &Update::HoveredChanged(is_hovered));
ctx.widget_state.request_accessibility = true;
ctx.widget_state.needs_accessibility = true;
}
ctx.widget_state.is_hovered = is_hovered;
});
}
// TODO - Make sure widgets are iterated from the bottom up.
// TODO - Document the iteration order for update_pointer pass.
for widget_id in prev_hovered_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.is_hovered
!= hovered_set.contains(&widget_id)
{
update_hovered_status_of(root, widget_id, &hovered_set);
}
}
for widget_id in next_hovered_path.iter().copied() {
if root.widget_arena.has(widget_id)
&& root.widget_arena.get_state_mut(widget_id).item.is_hovered
!= hovered_set.contains(&widget_id)
{
update_hovered_status_of(root, widget_id, &hovered_set);
}
}
}

5
masonry/src/render_root.rs
View File

@ -6,7 +6,7 @@ use std::collections::{HashMap, VecDeque};
use accesskit::{ActionRequest, TreeUpdate};
use parley::fontique::{self, Collection, CollectionOptions};
use parley::{FontContext, LayoutContext};
use tracing::warn;
use tracing::{info_span, warn};
use vello::kurbo::{self, Rect};
use vello::Scene;
@ -244,6 +244,7 @@ impl RenderRoot {
// --- MARK: PUB FUNCTIONS ---
pub fn handle_pointer_event(&mut self, event: PointerEvent) -> Handled {
let _span = info_span!("pointer_event");
let handled = run_on_pointer_event_pass(self, &event);
run_update_pointer_pass(self);
self.run_rewrite_passes();
@ -252,6 +253,7 @@ impl RenderRoot {
}
pub fn handle_text_event(&mut self, event: TextEvent) -> Handled {
let _span = info_span!("text_event");
let handled = run_on_text_event_pass(self, &event);
run_update_focus_pass(self);
self.run_rewrite_passes();
@ -260,6 +262,7 @@ impl RenderRoot {
}
pub fn handle_access_event(&mut self, event: ActionRequest) {
let _span = info_span!("access_event");
let Ok(id) = event.target.0.try_into() else {
warn!("Received ActionRequest with id 0. This shouldn't be possible.");
return;

1
masonry/src/widget/widget.rs
View File

@ -196,6 +196,7 @@ pub trait Widget: AsAny {
/// As methods recurse through the widget tree, trace spans are added for each child
/// widget visited, and popped when control flow goes back to the parent. This method
/// returns a static span (that you can use to filter traces and logs).
// TODO: Make include the widget's id?
fn make_trace_span(&self) -> Span {
trace_span!("Widget", r#type = self.short_type_name())
}