Add tracing to virtual_dom (#1949)
Address #1161; Add tracing to virtual dom: - Added a dependency on [tracing-fluent-assertions](https://github.com/tobz/tracing-fluent-assertions) for test cases - Added a test case showing tracing example log ``` 2024-02-28T21:52:25.266474Z TRACE dioxus_core::scope_context: providing context alloc::rc::Rc<dioxus_core::error_boundary::ErrorBoundary> (TypeId { t: 86211292795840746005296084033382154959 }) in app at packages/core/src/scope_context.rs:189 in dioxus_core::virtual_dom::VirtualDom::new 2024-02-28T21:52:25.266651Z TRACE dioxus_core::scope_context: looking for context generational_box::Owner<generational_box::sync::SyncStorage> (TypeId { t: 16187079142358387300491255137481079601 }) in app at packages/core/src/scope_context.rs:106 in dioxus_core::scope_arena::render with scope: app in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266662Z TRACE dioxus_core::scope_context: context generational_box::Owner<generational_box::sync::SyncStorage> (TypeId { t: 16187079142358387300491255137481079601 }) not found at packages/core/src/scope_context.rs:140 in dioxus_core::scope_arena::render with scope: app in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266671Z TRACE dioxus_core::scope_context: providing context generational_box::Owner<generational_box::sync::SyncStorage> (TypeId { t: 16187079142358387300491255137481079601 }) in app at packages/core/src/scope_context.rs:189 in dioxus_core::scope_arena::render with scope: app in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266713Z TRACE dioxus_core::scope_context: providing context dioxus_signals::reactive_context::ReactiveContext (TypeId { t: 86476382904980360086558195405008306005 }) in app at packages/core/src/scope_context.rs:189 in dioxus_core::scope_arena::render with scope: app in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266723Z TRACE dioxus_core::scope_context: looking for context generational_box::Owner (TypeId { t: 87785542931436862771411509553978749471 }) in app at packages/core/src/scope_context.rs:106 in dioxus_core::scope_arena::render with scope: app in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266730Z TRACE dioxus_core::scope_context: context generational_box::Owner (TypeId { t: 87785542931436862771411509553978749471 }) not found at packages/core/src/scope_context.rs:140 in dioxus_core::scope_arena::render with scope: app in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266769Z TRACE dioxus_core::scope_context: providing context generational_box::Owner (TypeId { t: 87785542931436862771411509553978749471 }) in app at packages/core/src/scope_context.rs:189 in dioxus_core::scope_arena::render with scope: app in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266828Z INFO dioxus_core::diff::node: creating template, self: VNode { vnode: VNodeInner { key: None, template: Cell { value: Template { name: "packages/core/tests/tracing.rs:60:5:1728", roots: [Element { tag: "div", namespace: None, attrs: [], children: [Element { tag: "button", namespace: None, attrs: [Dynamic { id: 0 }], children: [Text { text: "+" }] }, Element { tag: "button", namespace: None, attrs: [Dynamic { id: 1 }], children: [Text { text: "-" }] }, Element { tag: "ul", namespace: None, attrs: [], children: [Dynamic { id: 0 }] }] }], node_paths: [[0, 2, 0]], attr_paths: [[0, 0], [0, 1]] } }, dynamic_nodes: [Placeholder(VPlaceholder)], dynamic_attrs: [[Attribute { name: "onclick", value: Listener, namespace: None, volatile: false }], [Attribute { name: "onclick", value: Listener, namespace: None, volatile: false }]] }, mount: Cell { value: MountId(0) } }, mount: MountId(0) at packages/core/src/diff/node.rs:547 in dioxus_core::virtual_dom::VirtualDom::rebuild 2024-02-28T21:52:25.266896Z TRACE dioxus_core::virtual_dom: Calling 1 listeners at packages/core/src/virtual_dom.rs:695 in dioxus_core::virtual_dom::VirtualDom::handle_bubbling_event with parent: Some(ElementRef { path: ElementPath { path: [0, 0] }, mount: MountId(0) }), name: "click" in dioxus_core::virtual_dom::VirtualDom::handle_event with name: "click", data: Any { .. }, element: ElementId(2), bubbles: true 2024-02-28T21:52:25.266934Z TRACE dioxus_core::virtual_dom: Marking scope ScopeId(0) (app) as dirty at packages/core/src/virtual_dom.rs:379 in dioxus_core::virtual_dom::VirtualDom::process_events 2024-02-28T21:52:25.266997Z INFO dioxus_core::diff::node: creating template, self: VNode { vnode: VNodeInner { key: None, template: Cell { value: Template { name: "packages/core/tests/tracing.rs:71:37:2059", roots: [Dynamic { id: 0 }], node_paths: [[0]], attr_paths: [] } }, dynamic_nodes: [Component(VComponent { name: "ChildExample" })], dynamic_attrs: [] }, mount: Cell { value: MountId(1) } }, mount: MountId(1) at packages/core/src/diff/node.rs:547 in dioxus_core::virtual_dom::VirtualDom::render_immediate 2024-02-28T21:52:25.267026Z INFO dioxus_core::diff::node: creating template, self: VNode { vnode: VNodeInner { key: None, template: Cell { value: Template { name: "packages/core/tests/tracing.rs:81:5:2238", roots: [Element { tag: "li", namespace: None, attrs: [Dynamic { id: 0 }], children: [DynamicText { id: 0 }] }], node_paths: [[0, 0]], attr_paths: [[0]] } }, dynamic_nodes: [Text(VText { value: "0" })], dynamic_attrs: [[Attribute { name: "onmouseover", value: Listener, namespace: None, volatile: false }]] }, mount: Cell { value: MountId(2) } }, mount: MountId(2) at packages/core/src/diff/node.rs:547 in dioxus_core::virtual_dom::VirtualDom::render_immediate 2024-02-28T21:52:25.267061Z TRACE dioxus_core::virtual_dom: Calling 1 listeners at packages/core/src/virtual_dom.rs:695 in dioxus_core::virtual_dom::VirtualDom::handle_bubbling_event with parent: Some(ElementRef { path: ElementPath { path: [0, 0] }, mount: MountId(0) }), name: "click" in dioxus_core::virtual_dom::VirtualDom::handle_event with name: "click", data: Any { .. }, element: ElementId(2), bubbles: true 2024-02-28T21:52:25.267084Z TRACE dioxus_core::virtual_dom: Marking scope ScopeId(0) (app) as dirty at packages/core/src/virtual_dom.rs:379 in dioxus_core::virtual_dom::VirtualDom::process_events 2024-02-28T21:52:25.267131Z INFO dioxus_core::diff::node: creating template, self: VNode { vnode: VNodeInner { key: None, template: Cell { value: Template { name: "packages/core/tests/tracing.rs:71:37:2059", roots: [Dynamic { id: 0 }], node_paths: [[0]], attr_paths: [] } }, dynamic_nodes: [Component(VComponent { name: "ChildExample" })], dynamic_attrs: [] }, mount: Cell { value: MountId(3) } }, mount: MountId(3) at packages/core/src/diff/node.rs:547 in dioxus_core::virtual_dom::VirtualDom::render_immediate 2024-02-28T21:52:25.267157Z INFO dioxus_core::diff::node: creating template, self: VNode { vnode: VNodeInner { key: None, template: Cell { value: Template { name: "packages/core/tests/tracing.rs:81:5:2238", roots: [Element { tag: "li", namespace: None, attrs: [Dynamic { id: 0 }], children: [DynamicText { id: 0 }] }], node_paths: [[0, 0]], attr_paths: [[0]] } }, dynamic_nodes: [Text(VText { value: "1" })], dynamic_attrs: [[Attribute { name: "onmouseover", value: Listener, namespace: None, volatile: false }]] }, mount: Cell { value: MountId(4) } }, mount: MountId(4) at packages/core/src/diff/node.rs:547 in dioxus_core::virtual_dom::VirtualDom::render_immediate 2024-02-28T21:52:25.267206Z TRACE dioxus_core::virtual_dom: Calling 1 listeners at packages/core/src/virtual_dom.rs:695 in dioxus_core::virtual_dom::VirtualDom::handle_bubbling_event with parent: Some(ElementRef { path: ElementPath { path: [0, 0] }, mount: MountId(0) }), name: "click" in dioxus_core::virtual_dom::VirtualDom::handle_event with name: "click", data: Any { .. }, element: ElementId(2), bubbles: true 2024-02-28T21:52:25.267229Z TRACE dioxus_core::virtual_dom: Marking scope ScopeId(0) (app) as dirty at packages/core/src/virtual_dom.rs:379 in dioxus_core::virtual_dom::VirtualDom::process_events 2024-02-28T21:52:25.267274Z INFO dioxus_core::diff::node: creating template, self: VNode { vnode: VNodeInner { key: None, template: Cell { value: Template { name: "packages/core/tests/tracing.rs:71:37:2059", roots: [Dynamic { id: 0 }], node_paths: [[0]], attr_paths: [] } }, dynamic_nodes: [Component(VComponent { name: "ChildExample" })], dynamic_attrs: [] }, mount: Cell { value: MountId(5) } }, mount: MountId(5) at packages/core/src/diff/node.rs:547 in dioxus_core::virtual_dom::VirtualDom::render_immediate 2024-02-28T21:52:25.267297Z INFO dioxus_core::diff::node: creating template, self: VNode { vnode: VNodeInner { key: None, template: Cell { value: Template { name: "packages/core/tests/tracing.rs:81:5:2238", roots: [Element { tag: "li", namespace: None, attrs: [Dynamic { id: 0 }], children: [DynamicText { id: 0 }] }], node_paths: [[0, 0]], attr_paths: [[0]] } }, dynamic_nodes: [Text(VText { value: "2" })], dynamic_attrs: [[Attribute { name: "onmouseover", value: Listener, namespace: None, volatile: false }]] }, mount: Cell { value: MountId(6) } }, mount: MountId(6) at packages/core/src/diff/node.rs:547 in dioxus_core::virtual_dom::VirtualDom::render_immediate ```
This commit is contained in:
Jeremy Arnold authored and GitHub committed
1 parent
d9cb6dd1ec
commit
9ae3d14e67
4 files changed
+134
-4
No files matched your search
Generated
+13
@@ -2361,6 +2361,8 @@ dependencies = [
|
||||
"slab",
|
||||
"tokio",
|
||||
"tracing",
|
||||
"tracing-fluent-assertions",
|
||||
"tracing-subscriber",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
@@ -9707,6 +9709,17 @@ dependencies = [
|
||||
"valuable",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-fluent-assertions"
|
||||
version = "0.3.0"
|
||||
source = "registry+https://github.com/rust-lang/crates.io-index"
|
||||
checksum = "12de1a8c6bcfee614305e836308b596bbac831137a04c61f7e5b0b0bf2cfeaf6"
|
||||
dependencies = [
|
||||
"tracing",
|
||||
"tracing-core",
|
||||
"tracing-subscriber",
|
||||
]
|
||||
|
||||
[[package]]
|
||||
name = "tracing-futures"
|
||||
version = "0.2.5"
|
||||
|
||||
@@ -20,9 +20,11 @@ slab = { workspace = true }
|
||||
futures-channel = { workspace = true }
|
||||
tracing = { workspace = true }
|
||||
serde = { version = "1", features = ["derive"], optional = true }
|
||||
tracing-subscriber = "0.3.18"
|
||||
|
||||
[dev-dependencies]
|
||||
tokio = { workspace = true, features = ["full"] }
|
||||
tracing-fluent-assertions = "0.3.0"
|
||||
dioxus = { workspace = true }
|
||||
pretty_assertions = "1.3.0"
|
||||
rand = "0.8.5"
|
||||
|
||||
@@ -19,6 +19,7 @@ use futures_util::StreamExt;
|
||||
use rustc_hash::{FxHashMap, FxHashSet};
|
||||
use slab::Slab;
|
||||
use std::{any::Any, collections::BTreeSet, rc::Rc};
|
||||
use tracing::instrument;
|
||||
|
||||
/// A virtual node system that progresses user events and diffs UI trees.
|
||||
///
|
||||
@@ -303,6 +304,7 @@ impl VirtualDom {
|
||||
/// let mut dom = VirtualDom::new_from_root(VComponent::new(Example, SomeProps { name: "jane" }, "Example"));
|
||||
/// let mutations = dom.rebuild();
|
||||
/// ```
|
||||
#[instrument(skip(root), level = "trace", name = "VirtualDom::new")]
|
||||
pub(crate) fn new_with_component(root: impl AnyProps + 'static) -> Self {
|
||||
let (tx, rx) = futures_channel::mpsc::unbounded();
|
||||
|
||||
@@ -345,6 +347,7 @@ impl VirtualDom {
|
||||
}
|
||||
|
||||
/// Run a closure inside the dioxus runtime
|
||||
#[instrument(skip(self, f), level = "trace", name = "VirtualDom::in_runtime")]
|
||||
pub fn in_runtime<O>(&self, f: impl FnOnce() -> O) -> O {
|
||||
let _runtime = RuntimeGuard::new(self.runtime.clone());
|
||||
f()
|
||||
@@ -373,7 +376,13 @@ impl VirtualDom {
|
||||
return;
|
||||
};
|
||||
|
||||
tracing::trace!("Marking scope {:?} as dirty", id);
|
||||
tracing::event!(
|
||||
tracing::Level::TRACE,
|
||||
"Marking scope {:?} ({}) as dirty",
|
||||
id,
|
||||
scope.name
|
||||
);
|
||||
|
||||
self.dirty_scopes.insert(DirtyScope {
|
||||
height: scope.height(),
|
||||
id,
|
||||
@@ -389,6 +398,7 @@ impl VirtualDom {
|
||||
/// It is up to the listeners themselves to mark nodes as dirty.
|
||||
///
|
||||
/// If you have multiple events, you can call this method multiple times before calling "render_with_deadline"
|
||||
#[instrument(skip(self), level = "trace", name = "VirtualDom::handle_event")]
|
||||
pub fn handle_event(
|
||||
&mut self,
|
||||
name: &str,
|
||||
@@ -422,12 +432,14 @@ impl VirtualDom {
|
||||
/// ```rust, ignore
|
||||
/// let dom = VirtualDom::new(app);
|
||||
/// ```
|
||||
#[instrument(skip(self), level = "trace", name = "VirtualDom::wait_for_work")]
|
||||
pub async fn wait_for_work(&mut self) {
|
||||
// And then poll the futures
|
||||
self.poll_tasks().await;
|
||||
}
|
||||
|
||||
///
|
||||
#[instrument(skip(self), level = "trace", name = "VirtualDom::poll_tasks")]
|
||||
async fn poll_tasks(&mut self) {
|
||||
// Release the flush lock
|
||||
// This will cause all the flush wakers to immediately spring to life, which we will off with process_events
|
||||
@@ -461,6 +473,7 @@ impl VirtualDom {
|
||||
}
|
||||
|
||||
/// Process all events in the queue until there are no more left
|
||||
#[instrument(skip(self), level = "trace", name = "VirtualDom::process_events")]
|
||||
pub fn process_events(&mut self) {
|
||||
let _runtime = RuntimeGuard::new(self.runtime.clone());
|
||||
|
||||
@@ -478,7 +491,8 @@ impl VirtualDom {
|
||||
///
|
||||
/// The caller must ensure that the template references the same dynamic attributes and nodes as the original template.
|
||||
///
|
||||
/// This will only replace the the parent template, not any nested templates.
|
||||
/// This will only replace the parent template, not any nested templates.
|
||||
#[instrument(skip(self), level = "trace", name = "VirtualDom::replace_template")]
|
||||
pub fn replace_template(&mut self, template: Template) {
|
||||
self.register_template_first_byte_index(template);
|
||||
// iterating a slab is very inefficient, but this is a rare operation that will only happen during development so it's fine
|
||||
@@ -518,7 +532,7 @@ impl VirtualDom {
|
||||
/// The mutations item expects the RealDom's stack to be the root of the application.
|
||||
///
|
||||
/// Tasks will not be polled with this method, nor will any events be processed from the event queue. Instead, the
|
||||
/// root component will be ran once and then diffed. All updates will flow out as mutations.
|
||||
/// root component will be run once and then diffed. All updates will flow out as mutations.
|
||||
///
|
||||
/// All state stored in components will be completely wiped away.
|
||||
///
|
||||
@@ -533,6 +547,7 @@ impl VirtualDom {
|
||||
///
|
||||
/// apply_edits(edits);
|
||||
/// ```
|
||||
#[instrument(skip(self, to), level = "trace", name = "VirtualDom::rebuild")]
|
||||
pub fn rebuild(&mut self, to: &mut impl WriteMutations) {
|
||||
self.flush_templates(to);
|
||||
let _runtime = RuntimeGuard::new(self.runtime.clone());
|
||||
@@ -546,6 +561,7 @@ impl VirtualDom {
|
||||
|
||||
/// Render whatever the VirtualDom has ready as fast as possible without requiring an executor to progress
|
||||
/// suspended subtrees.
|
||||
#[instrument(skip(self, to), level = "trace", name = "VirtualDom::render_immediate")]
|
||||
pub fn render_immediate(&mut self, to: &mut impl WriteMutations) {
|
||||
self.flush_templates(to);
|
||||
|
||||
@@ -584,7 +600,8 @@ impl VirtualDom {
|
||||
/// The mutations will be thrown out, so it's best to use this method for things like SSR that have async content
|
||||
///
|
||||
/// We don't call "flush_sync" here since there's no sync work to be done. Futures will be progressed like usual,
|
||||
/// however any futures wating on flush_sync will remain pending
|
||||
/// however any futures waiting on flush_sync will remain pending
|
||||
#[instrument(skip(self), level = "trace", name = "VirtualDom::wait_for_suspense")]
|
||||
pub async fn wait_for_suspense(&mut self) {
|
||||
loop {
|
||||
if self.suspended_scopes.is_empty() {
|
||||
@@ -605,6 +622,7 @@ impl VirtualDom {
|
||||
}
|
||||
|
||||
/// Flush any queued template changes
|
||||
#[instrument(skip(self, to), level = "trace", name = "VirtualDom::flush_templates")]
|
||||
fn flush_templates(&mut self, to: &mut impl WriteMutations) {
|
||||
for template in self.queued_templates.drain(..) {
|
||||
to.register_template(template);
|
||||
@@ -632,6 +650,11 @@ impl VirtualDom {
|
||||
| | | <-- no, broke early
|
||||
| <-- no, broke early
|
||||
*/
|
||||
#[instrument(
|
||||
skip(self, uievent),
|
||||
level = "trace",
|
||||
name = "VirtualDom::handle_bubbling_event"
|
||||
)]
|
||||
fn handle_bubbling_event(
|
||||
&mut self,
|
||||
mut parent: Option<ElementRef>,
|
||||
@@ -670,6 +693,11 @@ impl VirtualDom {
|
||||
|
||||
// Now that we've accumulated all the parent attributes for the target element, call them in reverse order
|
||||
// We check the bubble state between each call to see if the event has been stopped from bubbling
|
||||
tracing::event!(
|
||||
tracing::Level::TRACE,
|
||||
"Calling {} listeners",
|
||||
listeners.len()
|
||||
);
|
||||
for listener in listeners.into_iter().rev() {
|
||||
if let AttributeValue::Listener(listener) = listener {
|
||||
self.runtime.rendering.set(false);
|
||||
@@ -688,6 +716,11 @@ impl VirtualDom {
|
||||
}
|
||||
|
||||
/// Call an event listener in the simplest way possible without bubbling upwards
|
||||
#[instrument(
|
||||
skip(self, uievent),
|
||||
level = "trace",
|
||||
name = "VirtualDom::handle_non_bubbling_event"
|
||||
)]
|
||||
fn handle_non_bubbling_event(&mut self, node: ElementRef, name: &str, uievent: Event<dyn Any>) {
|
||||
let el_ref = &self.mounts[node.mount.0].node;
|
||||
let node_template = el_ref.template.get();
|
||||
|
||||
@@ -0,0 +1,82 @@
|
||||
use dioxus::html::SerializedHtmlEventConverter;
|
||||
use dioxus::prelude::*;
|
||||
use dioxus_core::ElementId;
|
||||
use std::rc::Rc;
|
||||
use tracing_fluent_assertions::{AssertionRegistry, AssertionsLayer};
|
||||
use tracing_subscriber::{layer::SubscriberExt, Registry};
|
||||
|
||||
#[test]
|
||||
fn basic_tracing() {
|
||||
// setup tracing
|
||||
let assertion_registry = AssertionRegistry::default();
|
||||
let base_subscriber = Registry::default();
|
||||
// log to standard out for testing
|
||||
let std_out_log = tracing_subscriber::fmt::layer().pretty();
|
||||
let subscriber = base_subscriber
|
||||
.with(std_out_log)
|
||||
.with(AssertionsLayer::new(&assertion_registry));
|
||||
tracing::subscriber::set_global_default(subscriber).unwrap();
|
||||
|
||||
let new_virtual_dom = assertion_registry
|
||||
.build()
|
||||
.with_name("VirtualDom::new")
|
||||
.was_created()
|
||||
.was_entered_exactly(1)
|
||||
.was_closed()
|
||||
.finalize();
|
||||
|
||||
let edited_virtual_dom = assertion_registry
|
||||
.build()
|
||||
.with_name("VirtualDom::rebuild")
|
||||
.was_created()
|
||||
.was_entered_exactly(1)
|
||||
.was_closed()
|
||||
.finalize();
|
||||
|
||||
set_event_converter(Box::new(SerializedHtmlEventConverter));
|
||||
let mut dom = VirtualDom::new(app);
|
||||
|
||||
dom.rebuild(&mut dioxus_core::NoOpMutations);
|
||||
|
||||
new_virtual_dom.assert();
|
||||
edited_virtual_dom.assert();
|
||||
|
||||
for _ in 0..3 {
|
||||
dom.handle_event(
|
||||
"click",
|
||||
Rc::new(PlatformEventData::new(Box::<SerializedMouseData>::default())),
|
||||
ElementId(2),
|
||||
true,
|
||||
);
|
||||
dom.process_events();
|
||||
_ = dom.render_immediate_to_vec();
|
||||
}
|
||||
}
|
||||
|
||||
fn app() -> Element {
|
||||
let mut idx = use_signal(|| 0);
|
||||
let onhover = |_| println!("go!");
|
||||
|
||||
rsx! {
|
||||
div {
|
||||
button {
|
||||
onclick: move |_| {
|
||||
idx += 1;
|
||||
println!("Clicked");
|
||||
},
|
||||
"+"
|
||||
}
|
||||
button { onclick: move |_| idx -= 1, "-" }
|
||||
ul {
|
||||
{(0..idx()).map(|i| rsx! {
|
||||
ChildExample { i: i, onhover: onhover }
|
||||
})}
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
#[component]
|
||||
fn ChildExample(i: i32, onhover: EventHandler<MouseEvent>) -> Element {
|
||||
rsx! { li { onmouseover: move |e| onhover.call(e), "{i}" } }
|
||||
}
|
||||
Reference in new issue
Block a user