Tracing improvements

Cargo.lock

@@ -2,6 +2,15 @@
 # It is not intended for manual editing.
 version = 3
 
+[[package]]
+name = "aho-corasick"
+version = "1.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b2969dcb958b36655471fc61f7e416fa76033bdd4bfed0678d8fee1e2d07a1f0"
+dependencies = [
+ "memchr",
+]
+
 [[package]]
 name = "async-channel"
 version = "2.1.1"
@@ -302,6 +311,15 @@ dependencies = [
  "cc",
 ]
 
+[[package]]
+name = "matchers"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
+dependencies = [
+ "regex-automata 0.1.10",
+]
+
 [[package]]
 name = "memchr"
 version = "2.7.1"
@@ -460,6 +478,50 @@ dependencies = [
  "proc-macro2",
 ]
 
+[[package]]
+name = "regex"
+version = "1.10.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b62dbe01f0b06f9d8dc7d49e05a0785f153b00b2c227856282f671e0318c9b15"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-automata 0.4.5",
+ "regex-syntax 0.8.2",
+]
+
+[[package]]
+name = "regex-automata"
+version = "0.1.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
+dependencies = [
+ "regex-syntax 0.6.29",
+]
+
+[[package]]
+name = "regex-automata"
+version = "0.4.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5bb987efffd3c6d0d8f5f89510bb458559eab11e4f869acb20bf845e016259cd"
+dependencies = [
+ "aho-corasick",
+ "memchr",
+ "regex-syntax 0.8.2",
+]
+
+[[package]]
+name = "regex-syntax"
+version = "0.6.29"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1"
+
+[[package]]
+name = "regex-syntax"
+version = "0.8.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c08c74e62047bb2de4ff487b251e4a92e24f48745648451635cec7d591162d9f"
+
 [[package]]
 name = "rustc-hash"
 version = "1.1.0"
@@ -629,10 +691,14 @@ version = "0.3.18"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
 dependencies = [
+ "matchers",
  "nu-ansi-term",
+ "once_cell",
+ "regex",
  "sharded-slab",
  "smallvec",
  "thread_local",
+ "tracing",
  "tracing-core",
  "tracing-log",
 ]

Cargo.toml

@@ -28,7 +28,7 @@ mlua = { git = "https://github.com/mlua-rs/mlua.git", rev = "1754226c7440ec6c194
 [dev-dependencies]
 async-fs = "2.1"
 async-io = "2.3"
-tracing-subscriber = "0.3"
+tracing-subscriber = { version = "0.3", features = ["env-filter"] }
 
 [lints.clippy]
 all = { level = "deny", priority = -3 }

examples/basic_sleep.rs

@@ -10,7 +10,11 @@ use mlua_luau_runtime::Runtime;
 const MAIN_SCRIPT: &str = include_str!("./lua/basic_sleep.luau");
 
 pub fn main() -> LuaResult<()> {
-    tracing_subscriber::fmt::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+        .with_target(false)
+        .without_time()
+        .init();
 
     // Set up persistent Lua environment
     let lua = Lua::new();

examples/basic_spawn.rs

@@ -11,7 +11,11 @@ use mlua_luau_runtime::{LuaRuntimeExt, Runtime};
 const MAIN_SCRIPT: &str = include_str!("./lua/basic_spawn.luau");
 
 pub fn main() -> LuaResult<()> {
-    tracing_subscriber::fmt::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+        .with_target(false)
+        .without_time()
+        .init();
 
     // Set up persistent Lua environment
     let lua = Lua::new();

examples/callbacks.rs

@@ -9,7 +9,11 @@ use async_io::block_on;
 const MAIN_SCRIPT: &str = include_str!("./lua/callbacks.luau");
 
 pub fn main() -> LuaResult<()> {
-    tracing_subscriber::fmt::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+        .with_target(false)
+        .without_time()
+        .init();
 
     // Set up persistent Lua environment
     let lua = Lua::new();

examples/exit_code.rs

@@ -9,7 +9,11 @@ use mlua_luau_runtime::{Functions, Runtime};
 const MAIN_SCRIPT: &str = include_str!("./lua/exit_code.luau");
 
 pub fn main() -> LuaResult<()> {
-    tracing_subscriber::fmt::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+        .with_target(false)
+        .without_time()
+        .init();
 
     // Set up persistent Lua environment
     let lua = Lua::new();

examples/lots_of_threads.rs

@@ -12,7 +12,11 @@ const MAIN_SCRIPT: &str = include_str!("./lua/lots_of_threads.luau");
 const ONE_NANOSECOND: Duration = Duration::from_nanos(1);
 
 pub fn main() -> LuaResult<()> {
-    tracing_subscriber::fmt::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+        .with_target(false)
+        .without_time()
+        .init();
 
     // Set up persistent Lua environment
     let lua = Lua::new();

examples/scheduler_ordering.rs

@@ -11,7 +11,11 @@ use mlua_luau_runtime::{Functions, Runtime};
 const MAIN_SCRIPT: &str = include_str!("./lua/scheduler_ordering.luau");
 
 pub fn main() -> LuaResult<()> {
-    tracing_subscriber::fmt::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+        .with_target(false)
+        .without_time()
+        .init();
 
     // Set up persistent Lua environment
     let lua = Lua::new();

lib/runtime.rs

@@ -12,7 +12,7 @@ use futures_lite::prelude::*;
 use mlua::prelude::*;
 
 use async_executor::{Executor, LocalExecutor};
-use tracing::Instrument;
+use tracing::{debug, debug_span, instrument, Instrument};
 
 use crate::{
     error_callback::ThreadErrorCallback,
@@ -112,6 +112,14 @@ impl<'lua> Runtime<'lua> {
         }
     }
 
+    /**
+        Sets the current status of this runtime and emits relevant tracing events.
+    */
+    fn set_status(&self, status: Status) {
+        debug!(status = ?status, "status");
+        self.status.set(status);
+    }
+
     /**
         Returns the current status of this runtime.
     */
@@ -193,7 +201,6 @@ impl<'lua> Runtime<'lua> {
         thread: impl IntoLuaThread<'lua>,
         args: impl IntoLuaMulti<'lua>,
     ) -> LuaResult<ThreadId> {
-        tracing::debug!(deferred = false, "new runtime thread");
         let id = self.queue_spawn.push_item(self.lua, thread, args)?;
         self.result_map.track(id);
         Ok(id)
@@ -221,7 +228,6 @@ impl<'lua> Runtime<'lua> {
         thread: impl IntoLuaThread<'lua>,
         args: impl IntoLuaMulti<'lua>,
     ) -> LuaResult<ThreadId> {
-        tracing::debug!(deferred = true, "new runtime thread");
         let id = self.queue_defer.push_item(self.lua, thread, args)?;
         self.result_map.track(id);
         Ok(id)
@@ -266,6 +272,7 @@ impl<'lua> Runtime<'lua> {
         Panics if the given Lua state already has a runtime attached to it.
     */
     #[allow(clippy::too_many_lines)]
+    #[instrument(skip(self))]
     pub async fn run(&self) {
         /*
             Create new executors to use - note that we do not need create multiple executors
@@ -316,6 +323,8 @@ impl<'lua> Runtime<'lua> {
         let fut = async {
             let result_map = self.result_map.clone();
             let process_thread = |thread: LuaThread<'lua>, args| {
+                let span = debug_span!("process_thread");
+                let _guard = span.enter();
                 // NOTE: Thread may have been cancelled from Lua
                 // before we got here, so we need to check it again
                 if thread.status() == LuaThreadStatus::Resumable {
@@ -386,11 +395,6 @@ impl<'lua> Runtime<'lua> {
                     break;
                 }
 
-                // Emit traces
-                if num_processed > 0 {
-                    tracing::trace!(num_processed, "tasks_processed");
-                }
-
                 // Process spawned threads first, then deferred threads
                 let mut num_spawned = 0;
                 let mut num_deferred = 0;
@@ -402,9 +406,6 @@ impl<'lua> Runtime<'lua> {
                     process_thread(thread, args);
                     num_deferred += 1;
                 }
-                if num_spawned > 0 || num_deferred > 0 {
-                    tracing::trace!(num_spawned, num_deferred, "tasks_spawned");
-                }
 
                 // Process spawned futures
                 let mut num_futs = 0;
@@ -412,30 +413,30 @@ impl<'lua> Runtime<'lua> {
                     local_exec.spawn(fut).detach();
                     num_futs += 1;
                 }
-                if num_futs > 0 {
-                    tracing::trace!(num_futs, "futures_spawned");
-                }
 
                 // Empty executor = we didn't spawn any new Lua tasks
                 // above, and there are no remaining tasks to run later
-                if local_exec.is_empty()
+                let completed = local_exec.is_empty()
                     && self.queue_spawn.is_empty()
-                    && self.queue_defer.is_empty()
+                    && self.queue_defer.is_empty();
-                {
+                debug!(
+                    futures_spawned = num_futs,
+                    futures_processed = num_processed,
+                    lua_threads_spawned = num_spawned,
+                    lua_threads_deferred = num_deferred,
+                    "loop"
+                );
+                if completed {
                     break;
                 }
             }
         };
 
         // Run the executor inside a span until all lua threads complete
-        self.status.set(Status::Running);
+        self.set_status(Status::Running);
-        tracing::debug!("starting runtime");
+        let span = debug_span!("executor");
-
-        let span = tracing::debug_span!("run_executor");
         main_exec.run(fut).instrument(span.or_current()).await;
-
+        self.set_status(Status::Completed);
-        tracing::debug!("runtime completed");
-        self.status.set(Status::Completed);
 
         // Clean up
         self.lua