diff --git a/Cargo.lock b/Cargo.lock index de7afb9eb3..094de12a85 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -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" diff --git a/packages/core/Cargo.toml b/packages/core/Cargo.toml index 01ed1847d4..765f9b12f5 100644 --- a/packages/core/Cargo.toml +++ b/packages/core/Cargo.toml @@ -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" diff --git a/packages/core/src/virtual_dom.rs b/packages/core/src/virtual_dom.rs index 9e78f53db4..b1a4e12039 100644 --- a/packages/core/src/virtual_dom.rs +++ b/packages/core/src/virtual_dom.rs @@ -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(&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, @@ -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) { let el_ref = &self.mounts[node.mount.0].node; let node_template = el_ref.template.get(); diff --git a/packages/core/tests/tracing.rs b/packages/core/tests/tracing.rs new file mode 100644 index 0000000000..1fe04033d2 --- /dev/null +++ b/packages/core/tests/tracing.rs @@ -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::::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) -> Element { + rsx! { li { onmouseover: move |e| onhover.call(e), "{i}" } } +}