feat: Enable logging of timings (#2833)

swc_timer:
 - Add `Timer`.
 - Add `timer!()`.

node:
 - Enable logging.

Cargo.lock

@@ -1067,6 +1067,15 @@ dependencies = [
  "regex-automata",
 ]
 
+[[package]]
+name = "matchers"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
+dependencies = [
+ "regex-automata",
+]
+
 [[package]]
 name = "matches"
 version = "0.1.9"
@@ -1233,6 +1242,7 @@ dependencies = [
  "swc_node_base",
  "swc_node_bundler",
  "tracing",
+ "tracing-subscriber 0.3.2",
 ]
 
 [[package]]
@@ -3279,6 +3289,14 @@ dependencies = [
  "testing",
 ]
 
+[[package]]
+name = "swc_timer"
+version = "0.1.0"
+dependencies = [
+ "testing",
+ "tracing",
+]
+
 [[package]]
 name = "swc_visit"
 version = "0.2.8"
@@ -3345,7 +3363,7 @@ dependencies = [
  "swc_common",
  "testing_macros",
  "tracing",
- "tracing-subscriber",
+ "tracing-subscriber 0.2.25",
 ]
 
 [[package]]
@@ -3522,7 +3540,7 @@ dependencies = [
  "ansi_term 0.12.1",
  "chrono",
  "lazy_static",
- "matchers",
+ "matchers 0.0.1",
  "regex",
  "serde",
  "serde_json",
@@ -3535,6 +3553,24 @@ dependencies = [
  "tracing-serde",
 ]
 
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "7507ec620f809cdf07cccb5bc57b13069a88031b795efd4079b1c71b66c1613d"
+dependencies = [
+ "ansi_term 0.12.1",
+ "lazy_static",
+ "matchers 0.1.0",
+ "regex",
+ "sharded-slab",
+ "smallvec 1.7.0",
+ "thread_local",
+ "tracing",
+ "tracing-core",
+ "tracing-log",
+]
+
 [[package]]
 name = "try-lock"
 version = "0.2.3"

Cargo.toml

@@ -10,6 +10,7 @@ members = [
   "crates/swc_plugin_runner",
   "crates/swc_plugin_testing",
   "crates/swc_stylis",
+  "crates/swc_timer",
   "crates/wasm",
 ]
 

crates/node/Cargo.toml

@@ -31,4 +31,5 @@ swc_ecma_loader = {path = "../swc_ecma_loader"}
 swc_ecma_parser = {path = "../swc_ecma_parser"}
 swc_node_base = {path = "../swc_node_base"}
 swc_node_bundler = {path = "../swc_node_bundler"}
-tracing = {version = "0.1.28", features = ["release_max_level_off"]}
+tracing = {version = "0.1.28", features = ["release_max_level_info"]}
+tracing-subscriber = {version = "0.3.2", features = ["env-filter"]}

crates/node/src/lib.rs

@@ -10,6 +10,7 @@ use napi::{CallContext, Env, JsFunction, JsObject, JsUndefined};
 use std::{env, panic::set_hook, sync::Arc};
 use swc::{Compiler, TransformOutput};
 use swc_common::{self, sync::Lazy, FilePathMapping, SourceMap};
+use tracing_subscriber::EnvFilter;
 
 mod bundle;
 mod minify;
@@ -33,6 +34,13 @@ fn init(mut exports: JsObject) -> napi::Result<()> {
         }));
     }
 
+    let _ = tracing_subscriber::FmtSubscriber::builder()
+        .without_time()
+        .with_target(false)
+        .with_ansi(true)
+        .with_env_filter(EnvFilter::from_env("SWC_LOG"))
+        .try_init();
+
     exports.create_named_method("define", define_compiler_class)?;
 
     exports.create_named_method("minify", minify::minify)?;

crates/swc_bundler/scripts/instrument.sh

@@ -1,4 +1,4 @@
 #!/usr/bin/env bash
 set -eu
 
-cargo instruments --release -t time --example bundle --features concurrent,tracing/release_max_level_off -- $@
+cargo instruments --release -t time --example bundle --features concurrent,tracing/release_max_level_info -- $@

crates/swc_ecma_codegen/scripts/instrument.sh

@@ -1,4 +1,4 @@
 #!/usr/bin/env bash
 set -eu
 
-cargo instruments --release -t time --example gen --features tracing/release_max_level_off -- $@
+cargo instruments --release -t time --example gen --features tracing/release_max_level_info -- $@

crates/swc_ecma_minifier/scripts/instrument.sh

@@ -1,4 +1,4 @@
 #!/usr/bin/env bash
 set -eu
 
-cargo instruments --release -t time --open --features tracing/release_max_level_off --example perf -- $@
+cargo instruments --release -t time --open --features tracing/release_max_level_info --example perf -- $@

crates/swc_ecma_minifier/src/debug.rs

@@ -69,14 +69,13 @@ where
 /// If the cargo feature `debug` is disabled or the environment variable
 /// `SWC_RUN` is not `1`, this function is noop.
 pub(crate) fn invoke(module: &Module) {
-    static ENABLED: Lazy<bool> =
-        Lazy::new(|| cfg!(feature = "debug") && env::var("SWC_RUN").unwrap_or_default() == "1");
+    static ENABLED: Lazy<bool> = Lazy::new(|| env::var("SWC_RUN").unwrap_or_default() == "1");
 
     if cfg!(debug_assertions) {
         module.visit_with(&Invalid { span: DUMMY_SP }, &mut AssertValid);
     }
 
-    if !*ENABLED {
+    if !cfg!(feature = "debug") || !*ENABLED {
         return;
     }
 

crates/swc_ecma_parser/scripts/instrument.sh

@@ -1,4 +1,4 @@
 #!/usr/bin/env bash
 set -eu
 
-cargo instruments --release -t time --features log/release_max_level_off --example perf
+cargo instruments --release -t time --features log/release_max_level_info --example perf

crates/swc_timer/Cargo.toml

@@ -0,0 +1,17 @@
+[package]
+authors = ["강동윤 <kdy1997.dev@gmail.com>"]
+description = "Timings for swc"
+documentation = "https://rustdoc.swc.rs/swc_timer/"
+edition = "2018"
+license = "Apache-2.0/MIT"
+name = "swc_timer"
+repository = "https://github.com/swc-project/swc.git"
+version = "0.1.0"
+
+# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
+
+[dependencies]
+tracing = "0.1"
+
+[dev-dependencies]
+testing = {version = "0.15.1", path = "../testing"}

crates/swc_timer/src/lib.rs

@@ -0,0 +1,61 @@
+#[doc(hidden)]
+pub extern crate tracing;
+
+use tracing::{info, span::EnteredSpan};
+
+/// Prints time elapsed since `start` when dropped.
+///
+/// See [timer] for usages.
+pub struct Timer {
+    #[cfg(not(target_arch = "wasm32"))]
+    _span: EnteredSpan,
+    #[cfg(not(target_arch = "wasm32"))]
+    start: std::time::Instant,
+}
+
+impl Timer {
+    /// Don't use this directly. Use [timer] instead.
+    pub fn new(_span: EnteredSpan) -> Self {
+        Self {
+            #[cfg(not(target_arch = "wasm32"))]
+            _span,
+            #[cfg(not(target_arch = "wasm32"))]
+            start: std::time::Instant::now(),
+        }
+    }
+}
+
+#[cfg(not(target_arch = "wasm32"))]
+impl Drop for Timer {
+    fn drop(&mut self) {
+        let dur = self.start.elapsed();
+        info!(kind = "perf", "Done in {:?}", dur);
+    }
+}
+
+/// Creates a timer. For input arguments, see [tracing::span].
+///
+/// # Example usage
+///
+/// ```
+/// use swc_timer::timer;
+/// # let _logger = testing::init();
+/// let _timer = timer!("");
+/// ```
+///
+/// ## With arguments
+/// ```
+/// use swc_timer::timer;
+/// # let _logger = testing::init();
+/// let arg = "path";
+/// let _timer = timer!("bundle", path = arg);
+/// ```
+#[macro_export]
+macro_rules! timer {
+    ($($args:tt)*) => {{
+        #[cfg(not(target_arch = "wasm32"))]
+        let span = $crate::tracing::span!($crate::tracing::Level::INFO, $($args)*).entered();
+
+        $crate::Timer::new(span)
+    }};
+}

crates/swc_timer/tests/timer.rs

@@ -0,0 +1,11 @@
+use swc_timer::timer;
+
+#[test]
+fn logging() {
+    testing::run_test(false, |_, _| {
+        let _timer = timer!("operation");
+
+        Ok(())
+    })
+    .unwrap();
+}

scripts/instrument.sh

@@ -1,4 +1,4 @@
 #!/usr/bin/env bash
 set -eu
 
-cargo instruments --release -t time --bench typescript --features concurrent,tracing/release_max_level_off $@
+cargo instruments --release -t time --bench typescript --features concurrent,tracing/release_max_level_info $@