Replace custom logging by tracing (#2814)

* use tracing for logging

* embed spans in the scheduler for tracing

* fix feature soundness

* remove spans from scheduler for now

* feature soundness take 2

* use tracing::* throughout lib code

not yet in testing, and for some errors!

packages/yew-router/Cargo.toml

@@ -21,6 +21,7 @@ gloo = { version = "0.8", features = ["futures"] }
 route-recognizer = "0.3"
 serde = "1"
 serde_urlencoded = "0.7.1"
+tracing = "0.1.36"
 
 [dependencies.web-sys]
 version = "0.3"

packages/yew-router/src/switch.rs

@@ -1,6 +1,5 @@
 //! The [`Switch`] Component.
 
-use gloo::console;
 use yew::prelude::*;
 
 use crate::prelude::*;
@@ -41,7 +40,7 @@ where
     match route {
         Some(route) => props.render.emit(route),
         None => {
-            console::warn!("no route matched");
+            tracing::warn!("no route matched");
             Html::default()
         }
     }

packages/yew/Cargo.toml

@@ -33,6 +33,7 @@ bincode = { version = "1.3.3", optional = true }
 serde = { version = "1", features = ["derive"] }
 tokio = { version = "1.19", features = ["sync"] }
 tokio-stream = { version = "0.1.9", features = ["sync"] }
+tracing = "0.1.36"
 
 [dependencies.web-sys]
 version = "0.3"

packages/yew/src/app_handle.rs

@@ -24,6 +24,11 @@ where
     /// similarly to the `program` function in Elm. You should provide an initial model, `update`
     /// function which will update the state of the model and a `view` function which
     /// will render the model to a virtual DOM tree.
+    #[tracing::instrument(
+        level = tracing::Level::DEBUG,
+        name = "mount",
+        skip(props),
+    )]
     pub(crate) fn mount_with_props(host: Element, props: Rc<COMP::Properties>) -> Self {
         clear_element(&host);
         let app = Self {
@@ -42,6 +47,10 @@ where
     }
 
     /// Schedule the app for destruction
+    #[tracing::instrument(
+        level = tracing::Level::DEBUG,
+        skip_all,
+    )]
     pub fn destroy(self) {
         self.scope.destroy(false)
     }
@@ -74,6 +83,11 @@ mod feat_hydration {
     where
         COMP: BaseComponent,
     {
+        #[tracing::instrument(
+            level = tracing::Level::DEBUG,
+            name = "hydrate",
+            skip(props),
+        )]
         pub(crate) fn hydrate_with_props(host: Element, props: Rc<COMP::Properties>) -> Self {
             let app = Self {
                 scope: Scope::new(None),

packages/yew/src/dom_bundle/bnode.rs

@@ -2,7 +2,6 @@
 
 use std::fmt;
 
-use gloo::console;
 use web_sys::{Element, Node};
 
 use super::{BComp, BList, BPortal, BSubtree, BSuspense, BTag, BText};
@@ -54,7 +53,7 @@ impl ReconcileTarget for BNode {
             Self::Ref(ref node) => {
                 // Always remove user-defined nodes to clear possible parent references of them
                 if parent.remove_child(node).is_err() {
-                    console::warn!("Node not found to remove VRef");
+                    tracing::warn!("Node not found to remove VRef");
                 }
             }
             Self::Portal(bportal) => bportal.detach(root, parent, parent_to_detach),

packages/yew/src/dom_bundle/btag/mod.rs

@@ -7,7 +7,6 @@ use std::borrow::Cow;
 use std::hint::unreachable_unchecked;
 use std::ops::DerefMut;
 
-use gloo::console;
 use gloo::utils::document;
 use listeners::ListenerRegistration;
 pub use listeners::Registry;
@@ -84,7 +83,7 @@ impl ReconcileTarget for BTag {
             let result = parent.remove_child(&node);
 
             if result.is_err() {
-                console::warn!("Node not found to remove VTag");
+                tracing::warn!("Node not found to remove VTag");
             }
         }
         // It could be that the ref was already reused when rendering another element.

packages/yew/src/dom_bundle/btext.rs

@@ -1,6 +1,5 @@
 //! This module contains the bundle implementation of text [BText].
 
-use gloo::console;
 use gloo::utils::document;
 use web_sys::{Element, Text as TextNode};
 
@@ -21,7 +20,7 @@ impl ReconcileTarget for BText {
             let result = parent.remove_child(&self.text_node);
 
             if result.is_err() {
-                console::warn!("Node not found to remove VText");
+                tracing::warn!("Node not found to remove VText");
             }
         }
     }

packages/yew/src/dom_bundle/utils.rs

@@ -6,8 +6,18 @@ pub(super) fn insert_node(node: &Node, parent: &Element, next_sibling: Option<&N
         Some(next_sibling) => parent
             .insert_before(node, Some(next_sibling))
             .unwrap_or_else(|err| {
-                gloo::console::error!("failed to insert node", err, parent, next_sibling, node);
-                panic!("failed to insert tag before next sibling")
+                // Log normally, so we can inspect the nodes in console
+                gloo::console::error!(
+                    "failed to insert node before next sibling",
+                    err,
+                    parent,
+                    next_sibling,
+                    node
+                );
+                // Log via tracing for consistency
+                tracing::error!("failed to insert node before next sibling");
+                // Panic to short-curcuit and fail
+                panic!("failed to insert node before next sibling")
             }),
         None => parent.append_child(node).expect("failed to append child"),
     };

packages/yew/src/html/component/lifecycle.rs

@@ -38,7 +38,6 @@ pub(crate) enum ComponentRenderState {
         next_sibling: NodeRef,
         internal_ref: NodeRef,
     },
-
     #[cfg(feature = "ssr")]
     Ssr {
         sender: Option<crate::platform::sync::oneshot::Sender<Html>>,
@@ -238,6 +237,12 @@ pub(crate) struct ComponentState {
 }
 
 impl ComponentState {
+    #[tracing::instrument(
+        level = tracing::Level::DEBUG,
+        name = "create",
+        skip_all,
+        fields(component.id = scope.id),
+    )]
     fn new<COMP: BaseComponent>(
         initial_render_state: ComponentRenderState,
         scope: Scope<COMP>,
@@ -306,9 +311,6 @@ impl<COMP: BaseComponent> Runnable for CreateRunner<COMP> {
     fn run(self: Box<Self>) {
         let mut current_state = self.scope.state.borrow_mut();
         if current_state.is_none() {
-            #[cfg(debug_assertions)]
-            super::log_event(self.scope.id, "create");
-
             *current_state = Some(ComponentState::new(
                 self.initial_render_state,
                 self.scope.clone(),
@@ -320,28 +322,289 @@ impl<COMP: BaseComponent> Runnable for CreateRunner<COMP> {
     }
 }
 
-#[cfg(feature = "csr")]
-pub(crate) struct PropsUpdateRunner {
-    pub props: Option<Rc<dyn Any>>,
+pub(crate) struct UpdateRunner {
     pub state: Shared<Option<ComponentState>>,
-    pub next_sibling: Option<NodeRef>,
+}
+
+impl ComponentState {
+    #[tracing::instrument(
+        level = tracing::Level::DEBUG,
+        skip(self),
+        fields(component.id = self.comp_id)
+    )]
+    fn update(&mut self) -> bool {
+        let schedule_render = self.inner.flush_messages();
+        tracing::trace!(schedule_render);
+        schedule_render
+    }
+}
+
+impl Runnable for UpdateRunner {
+    fn run(self: Box<Self>) {
+        if let Some(state) = self.state.borrow_mut().as_mut() {
+            let schedule_render = state.update();
+
+            if schedule_render {
+                scheduler::push_component_render(
+                    state.comp_id,
+                    Box::new(RenderRunner {
+                        state: self.state.clone(),
+                    }),
+                );
+                // Only run from the scheduler, so no need to call `scheduler::start()`
+            }
+        }
+    }
+}
+
+pub(crate) struct DestroyRunner {
+    pub state: Shared<Option<ComponentState>>,
+    pub parent_to_detach: bool,
+}
+
+impl ComponentState {
+    #[tracing::instrument(
+        level = tracing::Level::DEBUG,
+        skip(self),
+        fields(component.id = self.comp_id)
+    )]
+    fn destroy(mut self, parent_to_detach: bool) {
+        self.inner.destroy();
+
+        match self.render_state {
+            #[cfg(feature = "csr")]
+            ComponentRenderState::Render {
+                bundle,
+                ref parent,
+                ref internal_ref,
+                ref root,
+                ..
+            } => {
+                bundle.detach(root, parent, parent_to_detach);
+
+                internal_ref.set(None);
+            }
+            // We need to detach the hydrate fragment if the component is not hydrated.
+            #[cfg(feature = "hydration")]
+            ComponentRenderState::Hydration {
+                ref root,
+                fragment,
+                ref parent,
+                ref internal_ref,
+                ..
+            } => {
+                fragment.detach(root, parent, parent_to_detach);
+
+                internal_ref.set(None);
+            }
+
+            #[cfg(feature = "ssr")]
+            ComponentRenderState::Ssr { .. } => {
+                let _ = parent_to_detach;
+            }
+        }
+    }
+}
+
+impl Runnable for DestroyRunner {
+    fn run(self: Box<Self>) {
+        if let Some(state) = self.state.borrow_mut().take() {
+            state.destroy(self.parent_to_detach);
+        }
+    }
+}
+
+pub(crate) struct RenderRunner {
+    pub state: Shared<Option<ComponentState>>,
+}
+
+impl ComponentState {
+    #[tracing::instrument(
+        level = tracing::Level::DEBUG,
+        skip_all,
+        fields(component.id = self.comp_id)
+    )]
+    fn render(&mut self, shared_state: &Shared<Option<ComponentState>>) {
+        match self.inner.view() {
+            Ok(vnode) => self.commit_render(shared_state, vnode),
+            Err(RenderError::Suspended(susp)) => self.suspend(shared_state, susp),
+        };
+    }
+
+    fn suspend(&mut self, shared_state: &Shared<Option<ComponentState>>, suspension: Suspension) {
+        // Currently suspended, we re-use previous root node and send
+        // suspension to parent element.
+
+        if suspension.resumed() {
+            // schedule a render immediately if suspension is resumed.
+            scheduler::push_component_render(
+                self.comp_id,
+                Box::new(RenderRunner {
+                    state: shared_state.clone(),
+                }),
+            );
+        } else {
+            // We schedule a render after current suspension is resumed.
+            let comp_scope = self.inner.any_scope();
+
+            let suspense_scope = comp_scope
+                .find_parent_scope::<BaseSuspense>()
+                .expect("To suspend rendering, a <Suspense /> component is required.");
+            let suspense = suspense_scope.get_component().unwrap();
+
+            let comp_id = self.comp_id;
+            let shared_state = shared_state.clone();
+            suspension.listen(Callback::from(move |_| {
+                scheduler::push_component_render(
+                    comp_id,
+                    Box::new(RenderRunner {
+                        state: shared_state.clone(),
+                    }),
+                );
+                scheduler::start();
+            }));
+
+            if let Some(ref last_suspension) = self.suspension {
+                if &suspension != last_suspension {
+                    // We remove previous suspension from the suspense.
+                    suspense.resume(last_suspension.clone());
+                }
+            }
+            self.suspension = Some(suspension.clone());
+
+            suspense.suspend(suspension);
+        }
+    }
+
+    fn commit_render(&mut self, shared_state: &Shared<Option<ComponentState>>, new_root: Html) {
+        // Currently not suspended, we remove any previous suspension and update
+        // normally.
+        if let Some(m) = self.suspension.take() {
+            let comp_scope = self.inner.any_scope();
+
+            let suspense_scope = comp_scope.find_parent_scope::<BaseSuspense>().unwrap();
+            let suspense = suspense_scope.get_component().unwrap();
+
+            suspense.resume(m);
+        }
+
+        match self.render_state {
+            #[cfg(feature = "csr")]
+            ComponentRenderState::Render {
+                ref mut bundle,
+                ref parent,
+                ref root,
+                ref next_sibling,
+                ref internal_ref,
+                ..
+            } => {
+                let scope = self.inner.any_scope();
+
+                #[cfg(feature = "hydration")]
+                next_sibling.debug_assert_not_trapped();
+
+                let new_node_ref =
+                    bundle.reconcile(root, &scope, parent, next_sibling.clone(), new_root);
+                internal_ref.link(new_node_ref);
+
+                let first_render = !self.has_rendered;
+                self.has_rendered = true;
+
+                scheduler::push_component_rendered(
+                    self.comp_id,
+                    Box::new(RenderedRunner {
+                        state: shared_state.clone(),
+                        first_render,
+                    }),
+                    first_render,
+                );
+            }
+
+            #[cfg(feature = "hydration")]
+            ComponentRenderState::Hydration {
+                ref mut fragment,
+                ref parent,
+                ref internal_ref,
+                ref next_sibling,
+                ref root,
+            } => {
+                // We schedule a "first" render to run immediately after hydration,
+                // to fix NodeRefs (first_node and next_sibling).
+                scheduler::push_component_priority_render(
+                    self.comp_id,
+                    Box::new(RenderRunner {
+                        state: shared_state.clone(),
+                    }),
+                );
+
+                let scope = self.inner.any_scope();
+
+                // This first node is not guaranteed to be correct here.
+                // As it may be a comment node that is removed afterwards.
+                // but we link it anyways.
+                let (node, bundle) = Bundle::hydrate(root, &scope, parent, fragment, new_root);
+
+                // We trim all text nodes before checking as it's likely these are whitespaces.
+                fragment.trim_start_text_nodes(parent);
+
+                assert!(fragment.is_empty(), "expected end of component, found node");
+
+                internal_ref.link(node);
+
+                self.render_state = ComponentRenderState::Render {
+                    root: root.clone(),
+                    bundle,
+                    parent: parent.clone(),
+                    internal_ref: internal_ref.clone(),
+                    next_sibling: next_sibling.clone(),
+                };
+            }
+
+            #[cfg(feature = "ssr")]
+            ComponentRenderState::Ssr { ref mut sender } => {
+                let _ = shared_state;
+                if let Some(tx) = sender.take() {
+                    tx.send(new_root).unwrap();
+                }
+            }
+        };
+    }
+}
+
+impl Runnable for RenderRunner {
+    fn run(self: Box<Self>) {
+        let mut state = self.state.borrow_mut();
+        let state = match state.as_mut() {
+            None => return, // skip for components that have already been destroyed
+            Some(state) => state,
+        };
+
+        state.render(&self.state);
+    }
 }
 
 #[cfg(feature = "csr")]
-impl Runnable for PropsUpdateRunner {
-    fn run(self: Box<Self>) {
-        let Self {
-            next_sibling,
-            props,
-            state: shared_state,
-        } = *self;
+mod feat_csr {
+    use super::*;
 
-        if let Some(state) = shared_state.borrow_mut().as_mut() {
+    pub(crate) struct PropsUpdateRunner {
+        pub state: Shared<Option<ComponentState>>,
+        pub props: Option<Rc<dyn Any>>,
+        pub next_sibling: Option<NodeRef>,
+    }
+
+    impl ComponentState {
+        #[tracing::instrument(
+            level = tracing::Level::DEBUG,
+            skip(self),
+            fields(component.id = self.comp_id)
+        )]
+        fn changed(&mut self, props: Option<Rc<dyn Any>>, next_sibling: Option<NodeRef>) -> bool {
             if let Some(next_sibling) = next_sibling {
                 // When components are updated, their siblings were likely also updated
                 // We also need to shift the bundle so next sibling will be synced to child
                 // components.
-                match state.render_state {
+                match self.render_state {
                     #[cfg(feature = "csr")]
                     ComponentRenderState::Render {
                         next_sibling: ref current_next_sibling,
@@ -393,299 +656,86 @@ impl Runnable for PropsUpdateRunner {
             let schedule_render = {
                 #[cfg(feature = "hydration")]
                 {
-                    if state.inner.creation_mode() == RenderMode::Hydration {
-                        should_render_hydration(props, state)
+                    if self.inner.creation_mode() == RenderMode::Hydration {
+                        should_render_hydration(props, self)
                     } else {
-                        should_render(props, state)
+                        should_render(props, self)
                     }
                 }
 
                 #[cfg(not(feature = "hydration"))]
-                should_render(props, state)
+                should_render(props, self)
             };
 
-            #[cfg(debug_assertions)]
-            super::log_event(
-                state.comp_id,
-                format!(
-                    "props_update(has_rendered={} schedule_render={})",
-                    state.has_rendered, schedule_render
-                ),
+            tracing::trace!(
+                "props_update(has_rendered={} schedule_render={})",
+                self.has_rendered,
+                schedule_render
             );
-
-            if schedule_render {
-                scheduler::push_component_render(
-                    state.comp_id,
-                    Box::new(RenderRunner {
-                        state: shared_state.clone(),
-                    }),
-                );
-                // Only run from the scheduler, so no need to call `scheduler::start()`
-            }
-        };
-    }
-}
-
-pub(crate) struct UpdateRunner {
-    pub state: Shared<Option<ComponentState>>,
-}
-
-impl Runnable for UpdateRunner {
-    fn run(self: Box<Self>) {
-        if let Some(state) = self.state.borrow_mut().as_mut() {
-            let schedule_render = state.inner.flush_messages();
-
-            #[cfg(debug_assertions)]
-            super::log_event(
-                state.comp_id,
-                format!("update(schedule_render={})", schedule_render),
-            );
-
-            if schedule_render {
-                scheduler::push_component_render(
-                    state.comp_id,
-                    Box::new(RenderRunner {
-                        state: self.state.clone(),
-                    }),
-                );
-                // Only run from the scheduler, so no need to call `scheduler::start()`
-            }
+            schedule_render
         }
     }
-}
 
-pub(crate) struct DestroyRunner {
-    pub state: Shared<Option<ComponentState>>,
-    pub parent_to_detach: bool,
-}
+    impl Runnable for PropsUpdateRunner {
+        fn run(self: Box<Self>) {
+            let Self {
+                next_sibling,
+                props,
+                state: shared_state,
+            } = *self;
 
-impl Runnable for DestroyRunner {
-    fn run(self: Box<Self>) {
-        if let Some(mut state) = self.state.borrow_mut().take() {
-            #[cfg(debug_assertions)]
-            super::log_event(state.comp_id, "destroy");
+            if let Some(state) = shared_state.borrow_mut().as_mut() {
+                let schedule_render = state.changed(props, next_sibling);
 
-            state.inner.destroy();
-
-            match state.render_state {
-                #[cfg(feature = "csr")]
-                ComponentRenderState::Render {
-                    bundle,
-                    ref parent,
-                    ref internal_ref,
-                    ref root,
-                    ..
-                } => {
-                    bundle.detach(root, parent, self.parent_to_detach);
-
-                    internal_ref.set(None);
+                if schedule_render {
+                    scheduler::push_component_render(
+                        state.comp_id,
+                        Box::new(RenderRunner {
+                            state: shared_state.clone(),
+                        }),
+                    );
+                    // Only run from the scheduler, so no need to call `scheduler::start()`
                 }
-                // We need to detach the hydrate fragment if the component is not hydrated.
-                #[cfg(feature = "hydration")]
-                ComponentRenderState::Hydration {
-                    ref root,
-                    fragment,
-                    ref parent,
-                    ref internal_ref,
-                    ..
-                } => {
-                    fragment.detach(root, parent, self.parent_to_detach);
-
-                    internal_ref.set(None);
-                }
-
-                #[cfg(feature = "ssr")]
-                ComponentRenderState::Ssr { .. } => {
-                    let _ = self.parent_to_detach;
-                }
-            }
-        }
-    }
-}
-
-pub(crate) struct RenderRunner {
-    pub state: Shared<Option<ComponentState>>,
-}
-
-impl Runnable for RenderRunner {
-    fn run(self: Box<Self>) {
-        if let Some(state) = self.state.borrow_mut().as_mut() {
-            #[cfg(debug_assertions)]
-            super::log_event(state.comp_id, "render");
-
-            match state.inner.view() {
-                Ok(m) => self.render(state, m),
-                Err(RenderError::Suspended(m)) => self.suspend(state, m),
             };
         }
     }
-}
-
-impl RenderRunner {
-    fn suspend(&self, state: &mut ComponentState, suspension: Suspension) {
-        // Currently suspended, we re-use previous root node and send
-        // suspension to parent element.
-        let shared_state = self.state.clone();
-
-        let comp_id = state.comp_id;
-
-        if suspension.resumed() {
-            // schedule a render immediately if suspension is resumed.
-            scheduler::push_component_render(
-                comp_id,
-                Box::new(RenderRunner {
-                    state: shared_state,
-                }),
-            );
-        } else {
-            // We schedule a render after current suspension is resumed.
-            let comp_scope = state.inner.any_scope();
-
-            let suspense_scope = comp_scope
-                .find_parent_scope::<BaseSuspense>()
-                .expect("To suspend rendering, a <Suspense /> component is required.");
-            let suspense = suspense_scope.get_component().unwrap();
-
-            suspension.listen(Callback::from(move |_| {
-                scheduler::push_component_render(
-                    comp_id,
-                    Box::new(RenderRunner {
-                        state: shared_state.clone(),
-                    }),
-                );
-                scheduler::start();
-            }));
-
-            if let Some(ref last_suspension) = state.suspension {
-                if &suspension != last_suspension {
-                    // We remove previous suspension from the suspense.
-                    suspense.resume(last_suspension.clone());
-                }
-            }
-            state.suspension = Some(suspension.clone());
-
-            suspense.suspend(suspension);
-        }
-    }
-
-    fn render(&self, state: &mut ComponentState, new_root: Html) {
-        // Currently not suspended, we remove any previous suspension and update
-        // normally.
-        if let Some(m) = state.suspension.take() {
-            let comp_scope = state.inner.any_scope();
-
-            let suspense_scope = comp_scope.find_parent_scope::<BaseSuspense>().unwrap();
-            let suspense = suspense_scope.get_component().unwrap();
-
-            suspense.resume(m);
-        }
-
-        match state.render_state {
-            #[cfg(feature = "csr")]
-            ComponentRenderState::Render {
-                ref mut bundle,
-                ref parent,
-                ref root,
-                ref next_sibling,
-                ref internal_ref,
-                ..
-            } => {
-                let scope = state.inner.any_scope();
-
-                #[cfg(feature = "hydration")]
-                next_sibling.debug_assert_not_trapped();
-
-                let new_node_ref =
-                    bundle.reconcile(root, &scope, parent, next_sibling.clone(), new_root);
-                internal_ref.link(new_node_ref);
-
-                let first_render = !state.has_rendered;
-                state.has_rendered = true;
-
-                scheduler::push_component_rendered(
-                    state.comp_id,
-                    Box::new(RenderedRunner {
-                        state: self.state.clone(),
-                        first_render,
-                    }),
-                    first_render,
-                );
-            }
-
-            #[cfg(feature = "hydration")]
-            ComponentRenderState::Hydration {
-                ref mut fragment,
-                ref parent,
-                ref internal_ref,
-                ref next_sibling,
-                ref root,
-            } => {
-                // We schedule a "first" render to run immediately after hydration,
-                // to fix NodeRefs (first_node and next_sibling).
-                scheduler::push_component_priority_render(
-                    state.comp_id,
-                    Box::new(RenderRunner {
-                        state: self.state.clone(),
-                    }),
-                );
-
-                let scope = state.inner.any_scope();
-
-                // This first node is not guaranteed to be correct here.
-                // As it may be a comment node that is removed afterwards.
-                // but we link it anyways.
-                let (node, bundle) = Bundle::hydrate(root, &scope, parent, fragment, new_root);
-
-                // We trim all text nodes before checking as it's likely these are whitespaces.
-                fragment.trim_start_text_nodes(parent);
-
-                assert!(fragment.is_empty(), "expected end of component, found node");
-
-                internal_ref.link(node);
-
-                state.render_state = ComponentRenderState::Render {
-                    root: root.clone(),
-                    bundle,
-                    parent: parent.clone(),
-                    internal_ref: internal_ref.clone(),
-                    next_sibling: next_sibling.clone(),
-                };
-            }
-
-            #[cfg(feature = "ssr")]
-            ComponentRenderState::Ssr { ref mut sender } => {
-                if let Some(tx) = sender.take() {
-                    tx.send(new_root).unwrap();
-                }
-            }
-        };
-    }
-}
-
-#[cfg(feature = "csr")]
-mod feat_csr {
-    use super::*;
 
     pub(crate) struct RenderedRunner {
         pub state: Shared<Option<ComponentState>>,
         pub first_render: bool,
     }
 
+    impl ComponentState {
+        #[tracing::instrument(
+            level = tracing::Level::DEBUG,
+            skip(self),
+            fields(component.id = self.comp_id)
+        )]
+        fn rendered(&mut self, first_render: bool) -> bool {
+            if self.suspension.is_none() {
+                self.inner.rendered(first_render);
+            }
+
+            #[cfg(feature = "hydration")]
+            {
+                self.pending_props.is_some()
+            }
+            #[cfg(not(feature = "hydration"))]
+            {
+                false
+            }
+        }
+    }
+
     impl Runnable for RenderedRunner {
         fn run(self: Box<Self>) {
             if let Some(state) = self.state.borrow_mut().as_mut() {
-                #[cfg(debug_assertions)]
-                super::super::log_event(state.comp_id, "rendered");
+                let has_pending_props = state.rendered(self.first_render);
 
-                if state.suspension.is_none() {
-                    state.inner.rendered(self.first_render);
-                }
-
-                #[cfg(feature = "hydration")]
-                if state.pending_props.is_some() {
+                if has_pending_props {
                     scheduler::push_component_props_update(Box::new(PropsUpdateRunner {
-                        props: None,
                         state: self.state.clone(),
+                        props: None,
                         next_sibling: None,
                     }));
                 }
@@ -695,7 +745,7 @@ mod feat_csr {
 }
 
 #[cfg(feature = "csr")]
-use feat_csr::*;
+pub(super) use feat_csr::*;
 
 #[cfg(target_arch = "wasm32")]
 #[cfg(test)]

packages/yew/src/html/component/mod.rs

@@ -18,42 +18,6 @@ pub use scope::{AnyScope, Scope, SendAsMessage};
 
 use super::{Html, HtmlResult, IntoHtmlResult};
 
-#[cfg(debug_assertions)]
-#[cfg(any(feature = "csr", feature = "ssr"))]
-mod feat_csr_ssr {
-    use wasm_bindgen::prelude::wasm_bindgen;
-    use wasm_bindgen::JsValue;
-
-    thread_local! {
-         static EVENT_HISTORY: std::cell::RefCell<std::collections::HashMap<usize, Vec<String>>>
-            = Default::default();
-    }
-
-    /// Push [Component] event to lifecycle debugging registry
-    pub(crate) fn log_event(comp_id: usize, event: impl ToString) {
-        EVENT_HISTORY.with(|h| {
-            h.borrow_mut()
-                .entry(comp_id)
-                .or_default()
-                .push(event.to_string())
-        });
-    }
-
-    /// Get [Component] event log from lifecycle debugging registry
-    #[wasm_bindgen(js_name = "yewGetEventLog")]
-    pub fn _get_event_log(comp_id: usize) -> Option<Vec<JsValue>> {
-        EVENT_HISTORY.with(|h| {
-            Some(
-                h.borrow()
-                    .get(&comp_id)?
-                    .iter()
-                    .map(|l| (*l).clone().into())
-                    .collect(),
-            )
-        })
-    }
-}
-
 #[cfg(feature = "hydration")]
 #[derive(Debug, Clone, Copy, PartialEq)]
 pub(crate) enum RenderMode {
@@ -63,10 +27,6 @@ pub(crate) enum RenderMode {
     Ssr,
 }
 
-#[cfg(debug_assertions)]
-#[cfg(any(feature = "csr", feature = "ssr"))]
-pub(crate) use feat_csr_ssr::*;
-
 /// The [`Component`]'s context. This contains component's [`Scope`] and props and
 /// is passed to every lifecycle method.
 #[derive(Debug)]

packages/yew/src/html/component/scope.rs

@@ -550,9 +550,6 @@ mod feat_csr {
         }
 
         pub(crate) fn reuse(&self, props: Rc<COMP::Properties>, next_sibling: NodeRef) {
-            #[cfg(debug_assertions)]
-            super::super::log_event(self.id, "reuse");
-
             schedule_props_update(self.state.clone(), props, next_sibling)
         }
     }
@@ -644,10 +641,10 @@ mod feat_hydration {
             // This is very helpful to see which component is failing during hydration
             // which means this component may not having a stable layout / differs between
             // client-side and server-side.
-            #[cfg(debug_assertions)]
-            super::super::log_event(
-                self.id,
-                format!("hydration(type = {})", std::any::type_name::<COMP>()),
+            tracing::trace!(
+                component.id = self.id,
+                "hydration(type = {})",
+                std::any::type_name::<COMP>()
             );
 
             let collectable = Collectable::for_component::<COMP>();

packages/yew/src/scheduler.rs

@@ -13,32 +13,76 @@ pub trait Runnable {
     fn run(self: Box<Self>);
 }
 
+struct QueueEntry {
+    task: Box<dyn Runnable>,
+}
+
+#[derive(Default)]
+struct FifoQueue {
+    inner: Vec<QueueEntry>,
+}
+
+impl FifoQueue {
+    fn push(&mut self, task: Box<dyn Runnable>) {
+        self.inner.push(QueueEntry { task });
+    }
+
+    fn drain_into(&mut self, queue: &mut Vec<QueueEntry>) {
+        queue.append(&mut self.inner);
+    }
+}
+
+#[derive(Default)]
+
+struct TopologicalQueue {
+    /// The Binary Tree Map guarantees components with lower id (parent) is rendered first
+    inner: BTreeMap<usize, QueueEntry>,
+}
+
+impl TopologicalQueue {
+    #[cfg(any(feature = "ssr", feature = "csr"))]
+    fn push(&mut self, component_id: usize, task: Box<dyn Runnable>) {
+        self.inner.insert(component_id, QueueEntry { task });
+    }
+
+    /// Take a single entry, preferring parents over children
+    fn pop_topmost(&mut self) -> Option<QueueEntry> {
+        // To be replaced with BTreeMap::pop_first once it is stable.
+        let key = *self.inner.keys().next()?;
+        self.inner.remove(&key)
+    }
+
+    /// Drain all entries, such that children are queued before parents
+    fn drain_post_order_into(&mut self, queue: &mut Vec<QueueEntry>) {
+        if self.inner.is_empty() {
+            return;
+        }
+        let rendered = std::mem::take(&mut self.inner);
+        // Children rendered lifecycle happen before parents.
+        queue.extend(rendered.into_values().rev());
+    }
+}
+
 /// This is a global scheduler suitable to schedule and run any tasks.
 #[derive(Default)]
 #[allow(missing_debug_implementations)] // todo
 struct Scheduler {
     // Main queue
-    main: Vec<Box<dyn Runnable>>,
+    main: FifoQueue,
 
     // Component queues
-    destroy: Vec<Box<dyn Runnable>>,
-    create: Vec<Box<dyn Runnable>>,
+    destroy: FifoQueue,
+    create: FifoQueue,
 
-    props_update: Vec<Box<dyn Runnable>>,
-    update: Vec<Box<dyn Runnable>>,
+    props_update: FifoQueue,
+    update: FifoQueue,
 
-    /// The Binary Tree Map guarantees components with lower id (parent) is rendered first and
-    /// no more than 1 render can be scheduled before a component is rendered.
-    ///
-    /// Parent can destroy child components but not otherwise, we can save unnecessary render by
-    /// rendering parent first.
-    render: BTreeMap<usize, Box<dyn Runnable>>,
-    render_first: BTreeMap<usize, Box<dyn Runnable>>,
-    render_priority: BTreeMap<usize, Box<dyn Runnable>>,
+    render: TopologicalQueue,
+    render_first: TopologicalQueue,
+    render_priority: TopologicalQueue,
 
-    /// Binary Tree Map to guarantee children rendered are always called before parent calls
-    rendered_first: BTreeMap<usize, Box<dyn Runnable>>,
-    rendered: BTreeMap<usize, Box<dyn Runnable>>,
+    rendered_first: TopologicalQueue,
+    rendered: TopologicalQueue,
 }
 
 /// Execute closure with a mutable reference to the scheduler
@@ -74,7 +118,7 @@ mod feat_csr_ssr {
     ) {
         with(|s| {
             s.create.push(create);
-            s.render_first.insert(component_id, first_render);
+            s.render_first.push(component_id, first_render);
         });
     }
 
@@ -86,7 +130,7 @@ mod feat_csr_ssr {
     /// Push a component render [Runnable]s to be executed
     pub(crate) fn push_component_render(component_id: usize, render: Box<dyn Runnable>) {
         with(|s| {
-            s.render.insert(component_id, render);
+            s.render.push(component_id, render);
         });
     }
 
@@ -110,9 +154,9 @@ mod feat_csr {
     ) {
         with(|s| {
             if first_render {
-                s.rendered_first.insert(component_id, rendered);
+                s.rendered_first.push(component_id, rendered);
             } else {
-                s.rendered.insert(component_id, rendered);
+                s.rendered.push(component_id, rendered);
             }
         });
     }
@@ -131,7 +175,7 @@ mod feat_hydration {
 
     pub(crate) fn push_component_priority_render(component_id: usize, render: Box<dyn Runnable>) {
         with(|s| {
-            s.render_priority.insert(component_id, render);
+            s.render_priority.push(component_id, render);
         });
     }
 }
@@ -141,6 +185,20 @@ pub(crate) use feat_hydration::*;
 
 /// Execute any pending [Runnable]s
 pub(crate) fn start_now() {
+    #[tracing::instrument(level = tracing::Level::DEBUG)]
+    fn scheduler_loop() {
+        let mut queue = vec![];
+        loop {
+            with(|s| s.fill_queue(&mut queue));
+            if queue.is_empty() {
+                break;
+            }
+            for r in queue.drain(..) {
+                r.task.run();
+            }
+        }
+    }
+
     thread_local! {
         // The lock is used to prevent recursion. If the lock cannot be acquired, it is because the
         // `start()` method is being called recursively as part of a `runnable.run()`.
@@ -149,16 +207,7 @@ pub(crate) fn start_now() {
 
     LOCK.with(|l| {
         if let Ok(_lock) = l.try_borrow_mut() {
-            let mut queue = vec![];
-            loop {
-                with(|s| s.fill_queue(&mut queue));
-                if queue.is_empty() {
-                    break;
-                }
-                for r in queue.drain(..) {
-                    r.run();
-                }
-            }
+            scheduler_loop();
         }
     });
 }
@@ -196,13 +245,13 @@ impl Scheduler {
     /// This method is optimized for typical usage, where possible, but does not break on
     /// non-typical usage (like scheduling renders in [crate::Component::create()] or
     /// [crate::Component::rendered()] calls).
-    fn fill_queue(&mut self, to_run: &mut Vec<Box<dyn Runnable>>) {
+    fn fill_queue(&mut self, to_run: &mut Vec<QueueEntry>) {
         // Placed first to avoid as much needless work as possible, handling all the other events.
         // Drained completely, because they are the highest priority events anyway.
-        to_run.append(&mut self.destroy);
+        self.destroy.drain_into(to_run);
 
         // Create events can be batched, as they are typically just for object creation
-        to_run.append(&mut self.create);
+        self.create.drain_into(to_run);
 
         // These typically do nothing and don't spawn any other events - can be batched.
         // Should be run only after all first renders have finished.
@@ -215,52 +264,32 @@ impl Scheduler {
         //
         // Should be processed one at time, because they can spawn more create and rendered events
         // for their children.
-        //
-        // To be replaced with BTreeMap::pop_first once it is stable.
-        if let Some(r) = self
-            .render_first
-            .keys()
-            .next()
-            .cloned()
-            .and_then(|m| self.render_first.remove(&m))
-        {
+        if let Some(r) = self.render_first.pop_topmost() {
             to_run.push(r);
-        }
-
-        if !to_run.is_empty() {
             return;
         }
 
-        to_run.append(&mut self.props_update);
+        self.props_update.drain_into(to_run);
 
         // Priority rendering
         //
         // This is needed for hydration susequent render to fix node refs.
-        if let Some(r) = self
-            .render_priority
-            .keys()
-            .next()
-            .cloned()
-            .and_then(|m| self.render_priority.remove(&m))
-        {
+        if let Some(r) = self.render_priority.pop_topmost() {
             to_run.push(r);
             return;
         }
 
-        if !self.rendered_first.is_empty() {
-            let rendered_first = std::mem::take(&mut self.rendered_first);
-            // Children rendered lifecycle happen before parents.
-            to_run.extend(rendered_first.into_values().rev());
-        }
+        // Children rendered lifecycle happen before parents.
+        self.rendered_first.drain_post_order_into(to_run);
 
         // Updates are after the first render to ensure we always have the entire child tree
         // rendered, once an update is processed.
         //
         // Can be batched, as they can cause only non-first renders.
-        to_run.append(&mut self.update);
+        self.update.drain_into(to_run);
 
         // Likely to cause duplicate renders via component updates, so placed before them
-        to_run.append(&mut self.main);
+        self.main.drain_into(to_run);
 
         // Run after all possible updates to avoid duplicate renders.
         //
@@ -270,30 +299,16 @@ impl Scheduler {
             return;
         }
 
-        // To be replaced with BTreeMap::pop_first once it is stable.
         // Should be processed one at time, because they can spawn more create and rendered events
         // for their children.
-        if let Some(r) = self
-            .render
-            .keys()
-            .next()
-            .cloned()
-            .and_then(|m| self.render.remove(&m))
-        {
+        if let Some(r) = self.render.pop_topmost() {
             to_run.push(r);
-        }
-
-        // These typically do nothing and don't spawn any other events - can be batched.
-        // Should be run only after all renders have finished.
-        if !to_run.is_empty() {
             return;
         }
-
-        if !self.rendered.is_empty() {
-            let rendered = std::mem::take(&mut self.rendered);
-            // Children rendered lifecycle happen before parents.
-            to_run.extend(rendered.into_values().rev());
-        }
+        // These typically do nothing and don't spawn any other events - can be batched.
+        // Should be run only after all renders have finished.
+        // Children rendered lifecycle happen before parents.
+        self.rendered.drain_post_order_into(to_run);
     }
 }
 

packages/yew/src/server_renderer.rs

@@ -1,6 +1,7 @@
 use std::fmt;
 
 use futures::stream::{Stream, StreamExt};
+use tracing::Instrument;
 
 use crate::html::{BaseComponent, Scope};
 use crate::platform::io::{self, DEFAULT_BUF_SIZE};
@@ -92,13 +93,23 @@ where
     }
 
     /// Renders Yew Applications into a string Stream
+    #[tracing::instrument(
+        level = tracing::Level::DEBUG,
+        name = "render",
+        skip(self),
+        fields(hydratable = self.hydratable, capacity = self.capacity),
+    )]
     pub fn render_stream(self) -> impl Stream<Item = String> {
         let (mut w, r) = io::buffer(self.capacity);
 
         let scope = Scope::<COMP>::new(None);
+        let outer_span = tracing::Span::current();
         spawn_local(async move {
+            let render_span = tracing::debug_span!("render_stream_item");
+            render_span.follows_from(outer_span);
             scope
                 .render_into_stream(&mut w, self.props.into(), self.hydratable)
+                .instrument(render_span)
                 .await;
         });