feat: log tmux call execution time to logs (#2444)

Cargo.lock

@@ -313,9 +313,9 @@ checksum = "8f1fe948ff07f4bd06c30984e69f5b4899c516a3ef74f34df92a2df2ab535495"
 
 [[package]]
 name = "bytes"
-version = "1.10.0"
+version = "1.10.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "f61dac84819c6588b558454b194026eb1f09c293b9036ae9b159e74e73ab6cf9"
+checksum = "d71b6127be86fdcfddb610f7182ac57211d4b18a3e9c82eb2d17662f2227ad6a"
 
 [[package]]
 name = "cassowary"
@@ -708,9 +708,9 @@ dependencies = [
 
 [[package]]
 name = "either"
-version = "1.14.0"
+version = "1.15.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "b7914353092ddf589ad78f25c5c1c21b7f80b0ff8621e7c814c3485b5306da9d"
+checksum = "48c757948c5ede0e46177b7add2e67155f70e33c07fea8284df6576da70b3719"
 
 [[package]]
 name = "encode_unicode"
@@ -2595,9 +2595,9 @@ dependencies = [
 
 [[package]]
 name = "time"
-version = "0.3.37"
+version = "0.3.38"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "35e7868883861bd0e56d9ac6efcaaca0d6d5d82a2a7ec8209ff492c07cf37b21"
+checksum = "bb041120f25f8fbe8fd2dbe4671c7c2ed74d83be2e7a77529bf7e0790ae3f472"
 dependencies = [
  "deranged",
  "itoa",
@@ -2612,15 +2612,15 @@ dependencies = [
 
 [[package]]
 name = "time-core"
-version = "0.1.2"
+version = "0.1.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "ef927ca75afb808a4d64dd374f00a2adf8d0fcff8e7b184af886c3c87ec4a3f3"
+checksum = "765c97a5b985b7c11d7bc27fa927dc4fe6af3a6dfb021d28deb60d3bf51e76ef"
 
 [[package]]
 name = "time-macros"
-version = "0.2.19"
+version = "0.2.20"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "2834e6017e3e5e4b9834939793b282bc03b37a3336245fa820e35e233e2a85de"
+checksum = "e8093bc3e81c3bc5f7879de09619d06c9a5a5e45ca44dfeeb7225bae38005c5c"
 dependencies = [
  "num-conv",
  "time-core",

yazi-adapter/src/brand.rs

@@ -1,4 +1,4 @@
-use tracing::warn;
+use tracing::debug;
 use yazi_shared::env_exists;
 
 use crate::Mux;
@@ -63,7 +63,7 @@ impl Brand {
 			"xterm-ghostty" => return Some(B::Ghostty),
 			"rio" => return Some(B::Rio),
 			"rxvt-unicode-256color" => return Some(B::Urxvt),
-			_ => warn!("[Adapter] Unknown TERM: {term}"),
+			_ => {}
 		}
 		match program.as_str() {
 			"iTerm.app" => return Some(B::Iterm2),
@@ -76,11 +76,11 @@ impl Brand {
 			"Hyper" => return Some(B::Hyper),
 			"mintty" => return Some(B::Mintty),
 			"Apple_Terminal" => return Some(B::Apple),
-			_ => warn!("[Adapter] Unknown TERM_PROGRAM: {program}"),
+			_ => {}
 		}
-		match vars.into_iter().find(|&(s, _)| env_exists(s)) {
-			Some((_, brand)) => return Some(brand),
-			None => warn!("[Adapter] No special environment variables detected"),
+		if let Some((var, brand)) = vars.into_iter().find(|&(s, _)| env_exists(s)) {
+			debug!("Detected special environment variable: {var}");
+			return Some(brand);
 		}
 
 		None

yazi-adapter/src/emulator.rs

@@ -106,7 +106,9 @@ impl Emulator {
 	}
 
 	pub fn read_until_da1() -> String {
+		let now = std::time::Instant::now();
 		let h = tokio::spawn(Self::error_to_user());
+
 		let (buf, result) = AsyncStdin::default().read_until(Duration::from_millis(500), |b, buf| {
 			b == b'c'
 				&& buf.contains(&0x1b)
@@ -115,21 +117,26 @@ impl Emulator {
 
 		h.abort();
 		match result {
-			Ok(()) => debug!("read_until_da1: {buf:?}"),
-			Err(e) => error!("read_until_da1 failed: {buf:?}, error: {e:?}"),
+			Ok(()) => debug!("Terminal responded to DA1 in {:?}: {buf:?}", now.elapsed()),
+			Err(e) => {
+				error!("Terminal failed to respond to DA1 in {:?}: {buf:?}, error: {e:?}", now.elapsed())
+			}
 		}
 
 		String::from_utf8_lossy(&buf).into_owned()
 	}
 
 	pub fn read_until_dsr() -> String {
+		let now = std::time::Instant::now();
 		let (buf, result) = AsyncStdin::default().read_until(Duration::from_millis(100), |b, buf| {
 			b == b'n' && (buf.ends_with(b"\x1b[0n") || buf.ends_with(b"\x1b[3n"))
 		});
 
 		match result {
-			Ok(()) => debug!("read_until_dsr: {buf:?}"),
-			Err(e) => error!("read_until_dsr failed: {buf:?}, error: {e:?}"),
+			Ok(()) => debug!("Terminal responded to DSR in {:?}: {buf:?}", now.elapsed()),
+			Err(e) => {
+				error!("Terminal failed to respond to DSR in {:?}: {buf:?}, error: {e:?}", now.elapsed())
+			}
 		}
 		String::from_utf8_lossy(&buf).into_owned()
 	}

yazi-adapter/src/mux.rs

@@ -1,5 +1,6 @@
 use anyhow::Result;
 use tracing::error;
+use yazi_macro::time;
 
 use crate::{CLOSE, ESCAPE, Emulator, START, TMUX};
 
@@ -18,14 +19,18 @@ impl Mux {
 	}
 
 	pub fn tmux_passthrough() {
-		let child = std::process::Command::new("tmux")
-			.args(["set", "-p", "allow-passthrough", "on"])
-			.stdin(std::process::Stdio::null())
-			.stdout(std::process::Stdio::null())
-			.stderr(std::process::Stdio::piped())
-			.spawn();
+		let output = time!(
+			"Running `tmux set -p allow-passthrough on`",
+			std::process::Command::new("tmux")
+				.args(["set", "-p", "allow-passthrough", "on"])
+				.stdin(std::process::Stdio::null())
+				.stdout(std::process::Stdio::null())
+				.stderr(std::process::Stdio::piped())
+				.spawn()
+				.and_then(|c| c.wait_with_output())
+		);
 
-		match child.and_then(|c| c.wait_with_output()) {
+		match output {
 			Ok(o) if o.status.success() => {}
 			Ok(o) => {
 				error!(
@@ -68,9 +73,14 @@ impl Mux {
 		if !TMUX.get() {
 			return (term, program);
 		}
-		let Ok(output) = std::process::Command::new("tmux").arg("show-environment").output() else {
+
+		let Ok(output) = time!(
+			"Running `tmux show-environment`",
+			std::process::Command::new("tmux").arg("show-environment").output()
+		) else {
 			return (term, program);
 		};
+
 		for line in String::from_utf8_lossy(&output.stdout).lines() {
 			if let Some((k, v)) = line.trim().split_once('=') {
 				match k {

yazi-fm/src/term.rs

@@ -6,6 +6,7 @@ use cursor::RestoreCursor;
 use ratatui::{CompletedFrame, Frame, Terminal, backend::CrosstermBackend, buffer::Buffer, layout::Rect};
 use yazi_adapter::{Emulator, Mux};
 use yazi_config::{INPUT, MGR};
+use yazi_shared::SyncCell;
 
 static CSI_U: AtomicBool = AtomicBool::new(false);
 static BLINK: AtomicBool = AtomicBool::new(false);
@@ -19,6 +20,7 @@ pub(super) struct Term {
 
 impl Term {
 	pub(super) fn start() -> Result<Self> {
+		static SKIP: SyncCell<bool> = SyncCell::new(false);
 		let mut term = Self {
 			inner:       Terminal::new(CrosstermBackend::new(BufWriter::new(stderr())))?,
 			last_area:   Default::default(),
@@ -26,7 +28,7 @@ impl Term {
 		};
 
 		enable_raw_mode()?;
-		if yazi_adapter::TMUX.get() {
+		if SKIP.replace(true) && yazi_adapter::TMUX.get() {
 			yazi_adapter::Mux::tmux_passthrough();
 		}
 

yazi-macro/src/lib.rs

@@ -1,5 +1,6 @@
 mod asset;
 mod event;
+mod log;
 mod module;
 mod platform;
 mod stdio;

yazi-macro/src/log.rs

@@ -0,0 +1,19 @@
+#[macro_export]
+macro_rules! time {
+	($expr:expr) => {
+		$crate::time!(stringify!($expr), $expr)
+	};
+	($label:expr, $expr:expr) => {
+		$crate::time!($expr, "{}", $label)
+	};
+	($expr:expr, $fmt:expr, $($args:tt)*) => {{
+		if tracing::enabled!(tracing::Level::DEBUG) {
+			let start = std::time::Instant::now();
+			let result = $expr;
+			tracing::debug!("{} took {:?}", format_args!($fmt, $($args)*), start.elapsed());
+			result
+		} else {
+			$expr
+		}
+	}};
+}