refactor: Collect use of std::time::Instant into dedicated timer mo…

…dule (#1085)

crates/stc/src/main.rs

@@ -1,6 +1,6 @@
 extern crate swc_node_base;
 
-use std::{path::PathBuf, sync::Arc, time::Instant};
+use std::{path::PathBuf, sync::Arc};
 
 use anyhow::Error;
 use clap::Parser;
@@ -13,6 +13,7 @@ use stc_ts_type_checker::{
     loader::{DefaultFileLoader, ModuleLoader},
     Checker,
 };
+use stc_utils::perf_timer::PerfTimer;
 use swc_common::{
     errors::{ColorConfig, EmitterWriter, Handler},
     FileName, Globals, SourceMap, GLOBALS,
@@ -33,7 +34,7 @@ enum Command {
 
 #[tokio::main]
 async fn main() -> Result<(), Error> {
-    let start = Instant::now();
+    let timer = PerfTimer::log_info();
 
     env_logger::init();
 
@@ -57,18 +58,14 @@ async fn main() -> Result<(), Error> {
 
     rayon::ThreadPoolBuilder::new().build_global().unwrap();
 
-    {
-        let end = Instant::now();
-
-        log::info!("Initialization took {:?}", end - start);
-    }
+    timer.log("Initialization");
 
     let globals = Arc::<Globals>::default();
 
     match command {
         Command::Test(cmd) => {
             let libs = {
-                let start = Instant::now();
+                let timer = PerfTimer::log_info();
 
                 let mut libs = match cmd.libs {
                     Some(libs) => libs.iter().flat_map(|s| Lib::load(s)).collect::<Vec<_>>(),
@@ -77,9 +74,7 @@ async fn main() -> Result<(), Error> {
                 libs.sort();
                 libs.dedup();
 
-                let end = Instant::now();
-
-                log::info!("Loading builtin libraries took {:?}", end - start);
+                timer.log("Loading builtin libraries");
 
                 libs
             };
@@ -91,7 +86,7 @@ async fn main() -> Result<(), Error> {
             let path = PathBuf::from(cmd.file);
 
             {
-                let start = Instant::now();
+                let timer = PerfTimer::log_info();
 
                 let checker = Checker::new(
                     cm.clone(),
@@ -103,14 +98,11 @@ async fn main() -> Result<(), Error> {
 
                 checker.load_typings(&path, None, cmd.types.as_deref());
 
-                let end = Instant::now();
-
-                log::info!("Loading typing libraries took {:?}", end - start);
+                timer.log("Loading typing libraries");
             }
 
             let mut errors = vec![];
 
-            let start = Instant::now();
             GLOBALS.set(&globals, || {
                 let mut checker = Checker::new(
                     cm.clone(),
@@ -125,31 +117,26 @@ async fn main() -> Result<(), Error> {
                 errors.extend(checker.take_errors());
             });
 
-            let end = Instant::now();
-
-            log::info!("Checking took {:?}", end - start);
+            timer.log("Checking");
 
             {
-                let start = Instant::now();
+                let timer = PerfTimer::log_info();
+
                 for err in &errors {
                     err.emit(&handler);
                 }
 
-                let end = Instant::now();
-
                 log::info!("Found {} errors", errors.len());
 
-                log::info!("Error reporting took {:?}", end - start);
+                timer.log("Error reporting");
             }
         }
         Command::Lsp(cmd) => {
             cmd.run().await?;
         }
     }
 
-    let end = Instant::now();
-
-    log::info!("Done in {:?}", end - start);
+    timer.log("Done");
 
     Ok(())
 }

crates/stc_ts_file_analyzer/src/analyzer/expr/array.rs

@@ -1,4 +1,4 @@
-use std::{borrow::Cow, time::Instant};
+use std::borrow::Cow;
 
 use itertools::Itertools;
 use stc_ts_ast_rnode::{RArrayLit, RExpr, RExprOrSpread, RInvalid, RNumber, RTsLit};
@@ -15,6 +15,7 @@ use stc_utils::{
     cache::Freeze,
     dev_span,
     ext::{SpanExt, TypeVecExt},
+    perf_timer::PerfTimer,
 };
 use swc_atoms::js_word;
 use swc_common::{Span, Spanned, SyntaxContext};
@@ -588,12 +589,10 @@ impl Analyzer<'_, '_> {
     }
 
     pub(crate) fn get_iterator<'a>(&mut self, span: Span, ty: Cow<'a, Type>, opts: GetIteratorOpts) -> VResult<Cow<'a, Type>> {
-        let start = Instant::now();
+        let timer = PerfTimer::noop();
         let iterator = self.get_iterator_inner(span, ty, opts).context("tried to get iterator");
 
-        let end = Instant::now();
-
-        debug!(kind = "perf", op = "get_iterator", "get_iterator (time = {:?}", end - start);
+        debug!(kind = "perf", op = "get_iterator", "get_iterator (time = {:?}", timer.elapsed());
 
         let iterator = iterator?;
 

crates/stc_ts_file_analyzer/src/analyzer/expr/mod.rs

@@ -2,7 +2,7 @@ use std::{
     borrow::Cow,
     collections::HashMap,
     convert::{TryFrom, TryInto},
-    time::{Duration, Instant},
+    time::Duration,
 };
 
 use optional_chaining::is_obj_opt_chaining;
@@ -27,7 +27,7 @@ use stc_ts_types::{
     PropertySignature, QueryExpr, QueryType, QueryTypeMetadata, Readonly, StaticThis, ThisType, TplElem, TplType, TplTypeMetadata,
     TypeParamInstantiation,
 };
-use stc_utils::{cache::Freeze, dev_span, ext::TypeVecExt, panic_ctx, stack};
+use stc_utils::{cache::Freeze, dev_span, ext::TypeVecExt, panic_ctx, perf_timer::PerfTimer, stack};
 use swc_atoms::js_word;
 use swc_common::{SourceMapper, Span, Spanned, SyntaxContext, TypeEq, DUMMY_SP};
 use swc_ecma_ast::{op, EsVersion, TruePlusMinus, TsKeywordTypeKind, VarDeclKind};
@@ -1229,7 +1229,7 @@ impl Analyzer<'_, '_> {
 
         let span = span.with_ctxt(SyntaxContext::empty());
 
-        let start = Instant::now();
+        let timer = PerfTimer::noop();
         obj.assert_valid();
 
         // Try some easier assignments.
@@ -1353,17 +1353,16 @@ impl Analyzer<'_, '_> {
                 )
             })
         }
-        let end = Instant::now();
-        let dur = end - start;
 
-        if dur >= Duration::from_micros(100) {
+        let elapsed = timer.elapsed();
+        if elapsed >= Duration::from_micros(100) {
             let line_col = self.line_col(span);
             debug!(
                 kind = "perf",
                 op = "access_property",
                 "({}) access_property: (time = {:?})",
                 line_col,
-                end - start
+                elapsed
             );
         }
 

crates/stc_ts_file_analyzer/src/analyzer/expr/object.rs

@@ -1,12 +1,12 @@
-use std::{borrow::Cow, time::Instant};
+use std::borrow::Cow;
 
 use rnode::VisitMutWith;
 use stc_ts_ast_rnode::{RObjectLit, RPropOrSpread, RSpreadElement};
 use stc_ts_errors::{DebugExt, ErrorKind};
 use stc_ts_file_analyzer_macros::validator;
 use stc_ts_type_ops::{union_normalization::ObjectUnionNormalizer, Fix};
 use stc_ts_types::{Accessor, Key, MethodSignature, PropertySignature, Type, TypeElement, TypeLit, TypeParam, Union, UnionMetadata};
-use stc_utils::{cache::Freeze, dev_span};
+use stc_utils::{cache::Freeze, dev_span, perf_timer::PerfTimer};
 use swc_common::{Span, Spanned, SyntaxContext, TypeEq};
 use swc_ecma_ast::TsKeywordTypeKind;
 use tracing::debug;
@@ -60,12 +60,10 @@ impl Analyzer<'_, '_> {
     pub(super) fn normalize_union(&mut self, ty: &mut Type, preserve_specified: bool) {
         let _tracing = dev_span!("normalize_union");
 
-        let start = Instant::now();
+        let timer = PerfTimer::noop();
         ty.visit_mut_with(&mut ObjectUnionNormalizer { preserve_specified });
 
-        let end = Instant::now();
-
-        debug!("Normalized unions (time = {:?})", end - start);
+        debug!("Normalized unions (time = {:?})", timer.elapsed());
     }
 
     pub(crate) fn validate_type_literals(&mut self, ty: &Type, is_type_ann: bool) {

crates/stc_ts_file_analyzer/src/analyzer/generic/mod.rs

@@ -1,4 +1,4 @@
-use std::{borrow::Cow, cmp::min, collections::hash_map::Entry, mem::take, time::Instant};
+use std::{borrow::Cow, cmp::min, collections::hash_map::Entry, mem::take};
 
 use fxhash::{FxHashMap, FxHashSet};
 use itertools::{EitherOrBoth, Itertools};
@@ -21,7 +21,9 @@ use stc_ts_types::{
 use stc_ts_utils::MapWithMut;
 use stc_utils::{
     cache::{Freeze, ALLOW_DEEP_CLONE},
-    dev_span, stack,
+    dev_span,
+    perf_timer::PerfTimer,
+    stack,
 };
 use swc_atoms::js_word;
 use swc_common::{EqIgnoreSpan, Span, Spanned, SyntaxContext, TypeEq, DUMMY_SP};
@@ -114,7 +116,7 @@ impl Analyzer<'_, '_> {
             type_params.iter().map(|p| format!("{}, ", p.name)).collect::<String>()
         );
 
-        let start = Instant::now();
+        let timer = PerfTimer::noop();
 
         let mut inferred = InferData::default();
 
@@ -357,9 +359,7 @@ impl Analyzer<'_, '_> {
 
         let map = self.finalize_inference(span, type_params, inferred);
 
-        let end = Instant::now();
-
-        warn!("infer_arg_types is finished. (time = {:?})", end - start);
+        warn!("infer_arg_types is finished. (time = {:?})", timer.elapsed());
 
         Ok(map)
     }

crates/stc_ts_file_analyzer/src/analyzer/scope/mod.rs

@@ -5,7 +5,6 @@ use std::{
     iter,
     mem::{replace, take},
     slice,
-    time::Instant,
 };
 
 use fxhash::{FxHashMap, FxHashSet};
@@ -26,7 +25,9 @@ use stc_ts_types::{
 };
 use stc_utils::{
     cache::{AssertCloneCheap, Freeze, ALLOW_DEEP_CLONE},
-    dev_span, stack,
+    dev_span,
+    perf_timer::PerfTimer,
+    stack,
 };
 use swc_atoms::js_word;
 use swc_common::{util::move_map::MoveMap, Span, Spanned, SyntaxContext, TypeEq, DUMMY_SP};
@@ -2707,17 +2708,16 @@ impl Fold<Type> for Expander<'_, '_, '_> {
             _ => {}
         }
         let before = dump_type_as_string(&ty);
-        let start = Instant::now();
+        let timer = PerfTimer::noop();
         let expanded = self.expand_type(ty).fixed();
-        let end = Instant::now();
 
         if !self.analyzer.config.is_builtin {
             expanded.assert_valid();
         }
 
         debug!(
             "[expander (time = {:?})]: {} => {}",
-            end - start,
+            timer.elapsed(),
             before,
             dump_type_as_string(&expanded)
         );

crates/stc_ts_file_analyzer/src/analyzer/stmt/mod.rs

@@ -1,10 +1,8 @@
-use std::time::Instant;
-
 use rnode::VisitWith;
 use stc_ts_ast_rnode::{RBlockStmt, RBool, RDecl, RExpr, RExprStmt, RForStmt, RModuleItem, RStmt, RTsExprWithTypeArgs, RTsLit, RWithStmt};
 use stc_ts_errors::{DebugExt, ErrorKind};
 use stc_ts_types::{LitType, Type};
-use stc_utils::{dev_span, stack};
+use stc_utils::{dev_span, perf_timer::PerfTimer, stack};
 use swc_common::{Spanned, DUMMY_SP};
 use swc_ecma_utils::Value::Known;
 use tracing::{trace, warn};
@@ -42,7 +40,7 @@ impl Analyzer<'_, '_> {
         let _tracing = dev_span!("Stmt", line_col = &*line_col);
 
         warn!("Statement start");
-        let start = Instant::now();
+        let timer = PerfTimer::noop();
 
         if self.rule().always_strict && !self.rule().allow_unreachable_code && self.ctx.in_unreachable {
             if !matches!(s, RStmt::Decl(RDecl::TsInterface(..) | RDecl::TsTypeAlias(..))) {
@@ -57,14 +55,12 @@ impl Analyzer<'_, '_> {
 
         self.scope.return_values.in_conditional = old_in_conditional;
 
-        let end = Instant::now();
-
         warn!(
             kind = "perf",
             op = "validate (Stmt)",
             "({}): Statement validation done. (time = {:?}",
             line_col,
-            end - start
+            timer.elapsed()
         );
 
         Ok(())

crates/stc_ts_file_analyzer/src/env.rs

@@ -1,4 +1,4 @@
-use std::{collections::hash_map::Entry, error::Error, path::Path, sync::Arc, time::Instant};
+use std::{collections::hash_map::Entry, error::Error, path::Path, sync::Arc};
 
 use dashmap::DashMap;
 use once_cell::sync::{Lazy, OnceCell};
@@ -110,8 +110,6 @@ pub trait BuiltInGen: Sized {
     {
         info!("Merging builtin");
 
-        let start = Instant::now();
-
         let mut types = FxHashMap::default();
         let mut vars = FxHashMap::default();
         let mut storage = Builtin::default();
@@ -283,8 +281,6 @@ pub trait BuiltInGen: Sized {
             ty.freeze();
         }
 
-        let dur = Instant::now() - start;
-
         Self::new(vars, types)
     }
 }