feat(core): add tracing for vital functionality closes #5204 (#8289)

* feat(core): add tracing for vital functionality

* Update core/tauri-runtime-wry/src/lib.rs [skip ci]

* Update Cargo.toml [skip ci]

* tracing feature

* wry 0.24.6

* add change tag

* add tracing to CI test

* enhance spans for update check

* remove app from debug impl

Author: lucasfernog-crabnebula

.changes/tracing.md

@@ -0,0 +1,7 @@
+---
+"tauri": patch:enhance
+"tauri-runtime-wry": patch:enhance
+"tauri-macros": patch:enhance
+---
+
+Added tracing for window startup, plugins, `Window::eval`, events, IPC, updater and custom protocol request handlers behind the `tracing` feature flag.

.github/workflows/test-core.yml

@@ -56,7 +56,7 @@ jobs:
               key: api-all
             }
           - {
-              args: --features compression,wry,linux-protocol-headers,isolation,custom-protocol,api-all,cli,updater,system-tray,windows7-compat,http-multipart,test,
+              args: --features tracing,compression,wry,linux-protocol-headers,isolation,custom-protocol,api-all,cli,updater,system-tray,windows7-compat,http-multipart,test,
               key: all
             }
 

core/tauri-macros/Cargo.toml

@@ -16,7 +16,7 @@ readme = "README.md"
 proc-macro = true
 
 [dependencies]
-proc-macro2 = "1"
+proc-macro2 = { version = "1", features = ["span-locations"] }
 quote = "1"
 syn = { version = "1", features = [ "full" ] }
 heck = "0.4"
@@ -30,3 +30,4 @@ isolation = [ "tauri-codegen/isolation" ]
 shell-scope = [ "tauri-codegen/shell-scope" ]
 config-json5 = [ "tauri-codegen/config-json5", "tauri-utils/config-json5" ]
 config-toml = [ "tauri-codegen/config-toml", "tauri-utils/config-toml" ]
+tracing = []

core/tauri-macros/src/command/wrapper.rs

@@ -161,21 +161,51 @@ pub fn wrapper(attributes: TokenStream, item: TokenStream) -> TokenStream {
   }
 
   // body to the command wrapper or a `compile_error!` of an error occurred while parsing it.
-  let body = syn::parse::<WrapperAttributes>(attributes)
+  let (body, attributes) = syn::parse::<WrapperAttributes>(attributes)
     .map(|mut attrs| {
       if function.sig.asyncness.is_some() {
         attrs.execution_context = ExecutionContext::Async;
       }
       attrs
     })
-    .and_then(|attrs| match attrs.execution_context {
-      ExecutionContext::Async => body_async(&function, &invoke, attrs.argument_case),
-      ExecutionContext::Blocking => body_blocking(&function, &invoke, attrs.argument_case),
+    .and_then(|attrs| {
+      let body = match attrs.execution_context {
+        ExecutionContext::Async => body_async(&function, &invoke, attrs.argument_case),
+        ExecutionContext::Blocking => body_blocking(&function, &invoke, attrs.argument_case),
+      };
+      body.map(|b| (b, Some(attrs)))
     })
-    .unwrap_or_else(syn::Error::into_compile_error);
+    .unwrap_or_else(|e| (syn::Error::into_compile_error(e), None));
 
   let Invoke { message, resolver } = invoke;
 
+  let kind = match attributes.as_ref().map(|a| &a.execution_context) {
+    Some(ExecutionContext::Async) if function.sig.asyncness.is_none() => "sync_threadpool",
+    Some(ExecutionContext::Async) => "async",
+    Some(ExecutionContext::Blocking) => "sync",
+    _ => "sync",
+  };
+
+  let loc = function.span().start();
+  let line = loc.line;
+  let col = loc.column;
+
+  let maybe_span = if cfg!(feature = "tracing") {
+    quote!({
+      let _span = tracing::debug_span!(
+        "ipc::request::handler",
+        cmd = #message.command(),
+        kind = #kind,
+        loc.line = #line,
+        loc.col = #col,
+        is_internal = false,
+      )
+      .entered();
+    })
+  } else {
+    quote!()
+  };
+
   // Rely on rust 2018 edition to allow importing a macro from a path.
   quote!(
     #async_command_check
@@ -193,6 +223,8 @@ pub fn wrapper(attributes: TokenStream, item: TokenStream) -> TokenStream {
           #[allow(unused_variables)]
           let ::tauri::Invoke { message: #message, resolver: #resolver } = $invoke;
 
+          #maybe_span
+
           #body
       }};
     }
@@ -212,6 +244,20 @@ pub fn wrapper(attributes: TokenStream, item: TokenStream) -> TokenStream {
 fn body_async(function: &ItemFn, invoke: &Invoke, case: ArgumentCase) -> syn::Result<TokenStream2> {
   let Invoke { message, resolver } = invoke;
   parse_args(function, message, case).map(|args| {
+    #[cfg(feature = "tracing")]
+    quote! {
+      use tracing::Instrument;
+
+      let span = tracing::debug_span!("ipc::request::run");
+      #resolver.respond_async_serialized(async move {
+        let result = $path(#(#args?),*);
+        let kind = (&result).async_kind();
+        kind.future(result).await
+      }
+      .instrument(span));
+    }
+
+    #[cfg(not(feature = "tracing"))]
     quote! {
       #resolver.respond_async_serialized(async move {
         let result = $path(#(#args?),*);
@@ -241,7 +287,14 @@ fn body_blocking(
     Err(err) => return #resolver.invoke_error(err),
   });
 
+  let maybe_span = if cfg!(feature = "tracing") {
+    quote!(let _span = tracing::debug_span!("ipc::request::run").entered();)
+  } else {
+    quote!()
+  };
+
   Ok(quote! {
+    #maybe_span
     let result = $path(#(match #args #match_body),*);
     let kind = (&result).blocking_kind();
     kind.block(result, #resolver);

core/tauri-runtime-wry/Cargo.toml

@@ -13,12 +13,13 @@ exclude = [ "CHANGELOG.md", "/target" ]
 readme = "README.md"
 
 [dependencies]
-wry = { version = "0.24.4", default-features = false, features = [ "file-drop", "protocol" ] }
+wry = { version = "0.24.6", default-features = false, features = [ "file-drop", "protocol" ] }
 tauri-runtime = { version = "0.14.1", path = "../tauri-runtime" }
 tauri-utils = { version = "1.5.0", path = "../tauri-utils" }
 uuid = { version = "1", features = [ "v4" ] }
 rand = "0.8"
 raw-window-handle = "0.5"
+tracing = { version = "0.1", optional = true }
 
 [target."cfg(windows)".dependencies]
 webview2-com = "0.19.1"
@@ -48,3 +49,4 @@ objc-exception = [ "wry/objc-exception" ]
 global-shortcut = [ "tauri-runtime/global-shortcut" ]
 clipboard = [ "tauri-runtime/clipboard" ]
 linux-headers = [ "wry/linux-headers", "webkit2gtk/v2_36" ]
+tracing = [ "dep:tracing", "wry/tracing" ]

core/tauri-runtime-wry/src/lib.rs

@@ -244,6 +244,32 @@ impl<T: UserEvent> Context<T> {
   }
 }
 
+#[cfg(feature = "tracing")]
+#[derive(Debug, Clone, Default)]
+pub struct ActiveTraceSpanStore(Rc<RefCell<Vec<ActiveTracingSpan>>>);
+
+#[cfg(feature = "tracing")]
+impl ActiveTraceSpanStore {
+  pub fn remove_window_draw(&self, window_id: WindowId) {
+    let mut store = self.0.borrow_mut();
+    if let Some(index) = store
+      .iter()
+      .position(|t| matches!(t, ActiveTracingSpan::WindowDraw { id, span: _ } if id == &window_id))
+    {
+      store.remove(index);
+    }
+  }
+}
+
+#[cfg(feature = "tracing")]
+#[derive(Debug)]
+pub enum ActiveTracingSpan {
+  WindowDraw {
+    id: WindowId,
+    span: tracing::span::EnteredSpan,
+  },
+}
+
 #[derive(Debug, Clone)]
 pub struct DispatcherMainThreadContext<T: UserEvent> {
   pub window_target: EventLoopWindowTarget<Message<T>>,
@@ -255,6 +281,8 @@ pub struct DispatcherMainThreadContext<T: UserEvent> {
   pub windows: Rc<RefCell<HashMap<WebviewId, WindowWrapper>>>,
   #[cfg(all(desktop, feature = "system-tray"))]
   system_tray_manager: SystemTrayManager,
+  #[cfg(feature = "tracing")]
+  pub active_tracing_spans: ActiveTraceSpanStore,
 }
 
 // SAFETY: we ensure this type is only used on the main thread.
@@ -1135,7 +1163,10 @@ pub enum WindowMessage {
 
 #[derive(Debug, Clone)]
 pub enum WebviewMessage {
+  #[cfg(not(feature = "tracing"))]
   EvaluateScript(String),
+  #[cfg(feature = "tracing")]
+  EvaluateScript(String, Sender<()>, tracing::Span),
   #[allow(dead_code)]
   WebviewEvent(WebviewEvent),
   Print,
@@ -1651,6 +1682,21 @@ impl<T: UserEvent> Dispatch<T> for WryDispatcher<T> {
     )
   }
 
+  #[cfg(feature = "tracing")]
+  fn eval_script<S: Into<String>>(&self, script: S) -> Result<()> {
+    // use a channel so the EvaluateScript task uses the current span as parent
+    let (tx, rx) = channel();
+    getter!(
+      self,
+      rx,
+      Message::Webview(
+        self.window_id,
+        WebviewMessage::EvaluateScript(script.into(), tx, tracing::Span::current()),
+      )
+    )
+  }
+
+  #[cfg(not(feature = "tracing"))]
   fn eval_script<S: Into<String>>(&self, script: S) -> Result<()> {
     send_user_message(
       &self.context,
@@ -1962,6 +2008,8 @@ impl<T: UserEvent> Wry<T> {
         windows,
         #[cfg(all(desktop, feature = "system-tray"))]
         system_tray_manager,
+        #[cfg(feature = "tracing")]
+        active_tracing_spans: Default::default(),
       },
     };
 
@@ -2165,6 +2213,9 @@ impl<T: UserEvent> Runtime<T> for Wry<T> {
     #[cfg(all(desktop, feature = "system-tray"))]
     let system_tray_manager = self.context.main_thread.system_tray_manager.clone();
 
+    #[cfg(feature = "tracing")]
+    let active_tracing_spans = self.context.main_thread.active_tracing_spans.clone();
+
     #[cfg(all(desktop, feature = "global-shortcut"))]
     let global_shortcut_manager = self.context.main_thread.global_shortcut_manager.clone();
     #[cfg(all(desktop, feature = "global-shortcut"))]
@@ -2202,6 +2253,8 @@ impl<T: UserEvent> Runtime<T> for Wry<T> {
               clipboard_manager: clipboard_manager.clone(),
               #[cfg(all(desktop, feature = "system-tray"))]
               system_tray_manager: system_tray_manager.clone(),
+              #[cfg(feature = "tracing")]
+              active_tracing_spans: active_tracing_spans.clone(),
             },
             web_context,
           );
@@ -2226,6 +2279,8 @@ impl<T: UserEvent> Runtime<T> for Wry<T> {
             clipboard_manager: clipboard_manager.clone(),
             #[cfg(all(desktop, feature = "system-tray"))]
             system_tray_manager: system_tray_manager.clone(),
+            #[cfg(feature = "tracing")]
+            active_tracing_spans: active_tracing_spans.clone(),
           },
           web_context,
         );
@@ -2240,6 +2295,9 @@ impl<T: UserEvent> Runtime<T> for Wry<T> {
     let web_context = self.context.main_thread.web_context;
     let mut plugins = self.plugins;
 
+    #[cfg(feature = "tracing")]
+    let active_tracing_spans = self.context.main_thread.active_tracing_spans.clone();
+
     #[cfg(all(desktop, feature = "system-tray"))]
     let system_tray_manager = self.context.main_thread.system_tray_manager;
 
@@ -2272,6 +2330,8 @@ impl<T: UserEvent> Runtime<T> for Wry<T> {
             clipboard_manager: clipboard_manager.clone(),
             #[cfg(all(desktop, feature = "system-tray"))]
             system_tray_manager: system_tray_manager.clone(),
+            #[cfg(feature = "tracing")]
+            active_tracing_spans: active_tracing_spans.clone(),
           },
           &web_context,
         );
@@ -2295,6 +2355,8 @@ impl<T: UserEvent> Runtime<T> for Wry<T> {
           clipboard_manager: clipboard_manager.clone(),
           #[cfg(all(desktop, feature = "system-tray"))]
           system_tray_manager: system_tray_manager.clone(),
+          #[cfg(feature = "tracing")]
+          active_tracing_spans: active_tracing_spans.clone(),
         },
         &web_context,
       );
@@ -2314,6 +2376,8 @@ pub struct EventLoopIterationContext<'a, T: UserEvent> {
   pub clipboard_manager: Arc<Mutex<Clipboard>>,
   #[cfg(all(desktop, feature = "system-tray"))]
   pub system_tray_manager: SystemTrayManager,
+  #[cfg(feature = "tracing")]
+  pub active_tracing_spans: ActiveTraceSpanStore,
 }
 
 struct UserMessageContext {
@@ -2590,6 +2654,19 @@ fn handle_user_message<T: UserEvent>(
       }
     }
     Message::Webview(id, webview_message) => match webview_message {
+      #[cfg(feature = "tracing")]
+      WebviewMessage::EvaluateScript(script, tx, span) => {
+        let _span = span.entered();
+        if let Some(WindowHandle::Webview { inner: webview, .. }) =
+          windows.borrow().get(&id).and_then(|w| w.inner.as_ref())
+        {
+          if let Err(e) = webview.evaluate_script(&script) {
+            debug_eprintln!("{}", e);
+          }
+        }
+        tx.send(()).unwrap();
+      }
+      #[cfg(not(feature = "tracing"))]
       WebviewMessage::EvaluateScript(script) => {
         if let Some(WindowHandle::Webview { inner: webview, .. }) =
           windows.borrow().get(&id).and_then(|w| w.inner.as_ref())
@@ -2758,6 +2835,8 @@ fn handle_event_loop<T: UserEvent>(
     clipboard_manager,
     #[cfg(all(desktop, feature = "system-tray"))]
     system_tray_manager,
+    #[cfg(feature = "tracing")]
+    active_tracing_spans,
   } = context;
   if *control_flow != ControlFlow::Exit {
     *control_flow = ControlFlow::Wait;
@@ -2780,6 +2859,11 @@ fn handle_event_loop<T: UserEvent>(
       callback(RunEvent::Exit);
     }
 
+    #[cfg(feature = "tracing")]
+    Event::RedrawRequested(id) => {
+      active_tracing_spans.remove_window_draw(id);
+    }
+
     #[cfg(all(desktop, feature = "global-shortcut"))]
     Event::GlobalShortcutEvent(accelerator_id) => {
       for (id, handler) in &*global_shortcut_manager_handle.listeners.lock().unwrap() {
@@ -3123,6 +3207,14 @@ fn create_webview<T: UserEvent>(
   #[cfg(windows)]
   let proxy = context.proxy.clone();
 
+  #[cfg(feature = "tracing")]
+  let _webview_create_span = tracing::debug_span!("wry::webview::create").entered();
+  #[cfg(feature = "tracing")]
+  let window_draw_span = tracing::debug_span!("wry::window::draw").entered();
+  #[cfg(feature = "tracing")]
+  let window_create_span =
+    tracing::debug_span!(parent: &window_draw_span, "wry::window::create").entered();
+
   let window_event_listeners = WindowEventListeners::default();
 
   #[cfg(windows)]
@@ -3157,6 +3249,21 @@ fn create_webview<T: UserEvent>(
   let focused = window_builder.inner.window.focused;
   let window = window_builder.inner.build(event_loop).unwrap();
 
+  #[cfg(feature = "tracing")]
+  {
+    drop(window_create_span);
+
+    context
+      .main_thread
+      .active_tracing_spans
+      .0
+      .borrow_mut()
+      .push(ActiveTracingSpan::WindowDraw {
+        id: window.id(),
+        span: window_draw_span,
+      });
+  }
+
   webview_id_map.insert(window.id(), window_id);
 
   if window_builder.center {

core/tauri/Cargo.toml

@@ -94,6 +94,7 @@ png = { version = "0.17", optional = true }
 ico = { version = "0.2.0", optional = true }
 encoding_rs = "0.8.31"
 sys-locale = { version = "0.2.3", optional = true }
+tracing = { version = "0.1", optional = true }
 
 [target."cfg(any(target_os = \"macos\", windows, target_os = \"linux\", target_os = \"dragonfly\", target_os = \"freebsd\", target_os = \"openbsd\", target_os = \"netbsd\"))".dependencies]
 rfd = { version = "0.10", optional = true, features = [ "gtk3", "common-controls-v6" ] }
@@ -135,6 +136,7 @@ cargo_toml = "0.11"
 
 [features]
 default = [ "wry", "compression", "objc-exception" ]
+tracing = [ "dep:tracing", "tauri-macros/tracing", "tauri-runtime-wry/tracing" ]
 test = [ ]
 compression = [ "tauri-macros/compression", "tauri-utils/compression" ]
 wry = [ "tauri-runtime-wry" ]