Don't use full tracing spans in full-tree passes by default (#687)

This can be toggled using the `MASONRY_TRACE_PASSES` environment
variable.

This is as-discussed in [#xilem > Scrolling is insanely
laggy](https://xi.zulipchat.com/#narrow/channel/354396-xilem/topic/Scrolling.20is.20insanely.20laggy).
There are a few overlapping issues, but this *significantly* improves
performance in debug mode.

The main pass which was problematic was the compose pass, however this
also had a significant impact on the time taken by the
accessibility/paint passes.

This only applies to the passes which traverse the entire tree, so not
the targeted passes. I also chose to exclude update_disabled and
update_stashed, as those will not necessarily happen to all widgets.

This also significantly reduces the size of the created log files - see
[#masonry > Heavy amounts of logs with large
app](https://xi.zulipchat.com/#narrow/channel/317477-masonry/topic/Heavy.20amounts.20of.20logs.20with.20large.20app).
In most cases, if you're using the log file, you will be in development,
which means that you can hopefully recreate the issue with the logging
for the passes you need enabled.
This commit is contained in:
Daniel McNab 2024-10-21 10:51:34 +01:00 committed by GitHub
parent 771eb2f02f
commit 38415d65ca
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
9 changed files with 162 additions and 33 deletions

View File

@ -858,7 +858,6 @@ impl LayoutCtx<'_> {
/// [`WidgetPod::paint_insets`]: crate::widget::WidgetPod::paint_insets
pub fn set_paint_insets(&mut self, insets: impl Into<Insets>) {
let insets = insets.into();
trace!("set_paint_insets {:?}", insets);
self.widget_state.paint_insets = insets.nonnegative();
}
@ -900,7 +899,6 @@ impl LayoutCtx<'_> {
/// The provided value should be the distance from the *bottom* of the
/// widget to the baseline.
pub fn set_baseline_offset(&mut self, baseline: f64) {
trace!("set_baseline_offset {}", baseline);
self.widget_state.baseline_offset = baseline;
}
@ -978,7 +976,10 @@ impl LayoutCtx<'_> {
/// - It serves as a mask for painting operations of the widget's children (*not* the widget itself).
/// - Pointer events must be inside that path to reach the widget's children.
pub fn set_clip_path(&mut self, path: Rect) {
trace!("set_clip_path {:?}", path);
// We intentionally always log this because clip paths are:
// 1) Relatively rare in the tree
// 2) An easy potential source of items not being visible when expected
trace!("set_clip_path {path:?}");
self.widget_state.clip = Some(path);
// TODO - Updating the clip path may have
// other knock-on effects we'd need to document.

View File

@ -19,7 +19,10 @@ fn build_accessibility_tree(
rebuild_all: bool,
scale_factor: f64,
) {
let _span = widget.item.make_trace_span().entered();
let _span = global_state
.trace
.access
.then(|| widget.item.make_trace_span().entered());
let id = state.item.id;
if !rebuild_all && !state.item.needs_accessibility {
@ -27,11 +30,13 @@ fn build_accessibility_tree(
}
if rebuild_all || state.item.request_accessibility {
trace!(
"Building accessibility node for widget '{}' {}",
widget.item.short_type_name(),
id,
);
if global_state.trace.access {
trace!(
"Building accessibility node for widget '{}' {}",
widget.item.short_type_name(),
id,
);
}
let mut ctx = AccessCtx {
global_state,
@ -47,12 +52,14 @@ fn build_accessibility_tree(
let node = node.build();
let id: NodeId = ctx.widget_state.id.into();
trace!(
"Built node {} with role={:?}, default_action={:?}",
id.0,
node.role(),
node.default_action_verb(),
);
if ctx.global_state.trace.access {
trace!(
"Built node {} with role={:?}, default_action={:?}",
id.0,
node.role(),
node.default_action_verb(),
);
}
ctx.tree_update.nodes.push((id, node));
}

View File

@ -15,7 +15,10 @@ fn update_anim_for_widget(
mut state: ArenaMut<'_, WidgetState>,
elapsed_ns: u64,
) {
let _span = widget.item.make_trace_span().entered();
let _span = global_state
.trace
.anim
.then(|| widget.item.make_trace_span().entered());
if !state.item.needs_anim {
return;

View File

@ -17,7 +17,10 @@ fn compose_widget(
parent_moved: bool,
parent_translation: Vec2,
) {
let _span = widget.item.make_trace_span().entered();
let _span = global_state
.trace
.compose
.then(|| widget.item.make_trace_span().entered());
let moved = parent_moved || state.item.translation_changed;
let translation = parent_translation + state.item.translation + state.item.origin.to_vec2();

View File

@ -27,7 +27,8 @@ pub(crate) fn run_layout_on<W: Widget>(
let mut widget = parent_ctx.widget_children.get_child_mut(id).unwrap();
let mut state = parent_ctx.widget_state_children.get_child_mut(id).unwrap();
let _span = widget.item.make_trace_span().entered();
let trace = parent_ctx.global_state.trace.layout;
let _span = trace.then(|| widget.item.make_trace_span().entered());
let mut children_ids = SmallVec::new();
if cfg!(debug_assertions) {
@ -69,7 +70,9 @@ pub(crate) fn run_layout_on<W: Widget>(
state.item.request_accessibility = true;
bc.debug_check(widget.item.short_type_name());
trace!("Computing layout with constraints {:?}", bc);
if trace {
trace!("Computing layout with constraints {:?}", bc);
}
state.item.local_paint_rect = Rect::ZERO;
@ -108,12 +111,14 @@ pub(crate) fn run_layout_on<W: Widget>(
pod.id(),
);
}
trace!(
"Computed layout: size={}, baseline={}, insets={:?}",
new_size,
state.item.baseline_offset,
state.item.paint_insets,
);
if trace {
trace!(
"Computed layout: size={}, baseline={}, insets={:?}",
new_size,
state.item.baseline_offset,
state.item.paint_insets,
);
}
state.item.needs_layout = false;
state.item.is_expecting_place_child_call = true;

View File

@ -64,3 +64,105 @@ pub(crate) fn merge_state_up(arena: &mut WidgetArena, widget_id: WidgetId) {
parent_state_mut.item.merge_up(child_state_mut.item);
}
/// Masonry has a significant number of passes which may traverse a significant number of
/// items.
///
/// In most cases, including these elements in traces adds noise and makes operations extremely slow.
/// Because of this, we default these traces to false.
///
/// Using the default tracing filtering mechanism for this would be non-ideal, as it would prevent child
/// spans of the item from running, which may make end-user debugging harder.
///
/// The detailed traces for these passes therefore default to false, but can be enabled using the
/// `MASONRY_TRACE_PASSES` environment variable.
///
/// Note that passes which are bounded by depth (rather than absolute size) are never filtered out here.
pub(crate) struct PassTracing {
pub(crate) update_tree: bool,
pub(crate) anim: bool,
pub(crate) layout: bool,
/// Compose is the biggest offender, as it is likely caused by a mouse move.
pub(crate) compose: bool,
pub(crate) paint: bool,
pub(crate) access: bool,
}
impl PassTracing {
pub(crate) fn from_env() -> Self {
let env_var = match std::env::var("MASONRY_TRACE_PASSES") {
Ok(env_var) => env_var,
// If it's not set, don't show any passes.
Err(std::env::VarError::NotPresent) => return Self::unit(false),
Err(std::env::VarError::NotUnicode(value)) => {
tracing::error!(
?value,
"Couldn't parse `MASONRY_TRACE_PASSES` environment variable: Not valid UTF-8",
);
return Self::unit(false);
}
};
let env_var = env_var.trim();
if env_var.eq_ignore_ascii_case("all") {
return Self::unit(true);
}
let mut result = Self::unit(false);
let mut show_help = false;
let mut supported_passes = [
("update_tree", &mut result.update_tree),
("anim", &mut result.anim),
("layout", &mut result.layout),
("compose", &mut result.compose),
("paint", &mut result.paint),
("access", &mut result.access),
];
for input_name in env_var.split(',').map(str::trim) {
if input_name == "all" {
tracing::warn!(
"`MASONRY_TRACE_PASSES=all` cannot be meaningfully combined with other passes"
);
return Self::unit(true);
}
if let Some((_, value)) = supported_passes
.iter_mut()
.find(|(pass_name, _)| pass_name.eq_ignore_ascii_case(input_name))
{
if **value {
tracing::warn!(
pass = input_name,
"MASONRY_TRACE_PASSES: Enabled tracing for same pass twice"
);
}
**value = true;
} else {
tracing::warn!(pass = input_name, "MASONRY_TRACE_PASSES: Unknown pass");
show_help = true;
}
}
if show_help {
let supported_str = supported_passes
.iter()
.map(|(name, _)| name)
.copied()
.collect::<Vec<_>>()
.join(", ");
tracing::warn!(
"Supported passes for the `MASONRY_TRACE_PASSES` environment variable are {supported_str}"
);
}
result
}
/// A `PassTracing` where all the fields have the same `value`.
const fn unit(value: bool) -> Self {
Self {
update_tree: value,
anim: value,
layout: value,
compose: value,
paint: value,
access: value,
}
}
}

View File

@ -23,7 +23,8 @@ fn paint_widget(
mut state: ArenaMut<'_, WidgetState>,
debug_paint: bool,
) {
let _span = widget.item.make_trace_span().entered();
let trace = global_state.trace.paint;
let _span = trace.then(|| widget.item.make_trace_span().entered());
let id = state.item.id;
// TODO - Handle invalidation regions
@ -35,7 +36,9 @@ fn paint_widget(
debug_paint,
};
if ctx.widget_state.request_paint {
trace!("Painting widget '{}' {}", widget.item.short_type_name(), id,);
if trace {
trace!("Painting widget '{}' {}", widget.item.short_type_name(), id);
}
// TODO - Reserve scene
// https://github.com/linebender/xilem/issues/524

View File

@ -79,7 +79,8 @@ fn update_widget_tree(
mut widget: ArenaMut<'_, Box<dyn Widget>>,
mut state: ArenaMut<'_, WidgetState>,
) {
let _span = widget.item.make_trace_span().entered();
let trace = global_state.trace.update_tree;
let _span = trace.then(|| widget.item.make_trace_span().entered());
let id = state.item.id;
if !state.item.children_changed {
@ -137,10 +138,12 @@ fn update_widget_tree(
widget_children: widget.children.reborrow_mut(),
};
widget.item.update(&mut ctx, &Update::WidgetAdded);
trace!(
"{} received Update::WidgetAdded",
widget.item.short_type_name()
);
if trace {
trace!(
"{} received Update::WidgetAdded",
widget.item.short_type_name()
);
}
state.item.accepts_pointer_interaction = widget.item.accepts_pointer_interaction();
state.item.accepts_focus = widget.item.accepts_focus();
state.item.accepts_text_input = widget.item.accepts_text_input();

View File

@ -27,12 +27,12 @@ use crate::passes::event::{
use crate::passes::layout::run_layout_pass;
use crate::passes::mutate::{mutate_widget, run_mutate_pass};
use crate::passes::paint::run_paint_pass;
use crate::passes::recurse_on_children;
use crate::passes::update::{
run_update_disabled_pass, run_update_focus_chain_pass, run_update_focus_pass,
run_update_pointer_pass, run_update_scroll_pass, run_update_stashed_pass,
run_update_widget_tree_pass,
};
use crate::passes::{recurse_on_children, PassTracing};
use crate::text::TextBrush;
use crate::tree_arena::{ArenaMut, TreeArena};
use crate::widget::{WidgetArena, WidgetMut, WidgetRef, WidgetState};
@ -76,6 +76,7 @@ pub(crate) struct RenderRootState {
pub(crate) scenes: HashMap<WidgetId, Scene>,
/// Whether data set in the pointer pass has been invalidated.
pub(crate) needs_pointer_pass: bool,
pub(crate) trace: PassTracing,
}
pub(crate) struct MutateCallback {
@ -164,6 +165,7 @@ impl RenderRoot {
is_ime_active: false,
scenes: HashMap::new(),
needs_pointer_pass: false,
trace: PassTracing::from_env(),
},
widget_arena: WidgetArena {
widgets: TreeArena::new(),