diff --git a/Cargo.lock b/Cargo.lock index 2a146059b2..cfc9616618 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2736,6 +2736,7 @@ name = "stc_utils" version = "0.1.0" dependencies = [ "ahash 0.7.6", + "log", "once_cell", "rustc-hash", "scoped-tls", diff --git a/crates/stc/src/main.rs b/crates/stc/src/main.rs index add3056b02..0c026628d4 100644 --- a/crates/stc/src/main.rs +++ b/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::::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::>(), @@ -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,21 +117,18 @@ 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) => { @@ -147,9 +136,7 @@ async fn main() -> Result<(), Error> { } } - let end = Instant::now(); - - log::info!("Done in {:?}", end - start); + timer.log("Done"); Ok(()) } diff --git a/crates/stc_ts_file_analyzer/src/analyzer/expr/array.rs b/crates/stc_ts_file_analyzer/src/analyzer/expr/array.rs index c7c2332a62..7f83f205c1 100644 --- a/crates/stc_ts_file_analyzer/src/analyzer/expr/array.rs +++ b/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> { - 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?; diff --git a/crates/stc_ts_file_analyzer/src/analyzer/expr/mod.rs b/crates/stc_ts_file_analyzer/src/analyzer/expr/mod.rs index cdf9095880..0e93f2e255 100644 --- a/crates/stc_ts_file_analyzer/src/analyzer/expr/mod.rs +++ b/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 ); } diff --git a/crates/stc_ts_file_analyzer/src/analyzer/expr/object.rs b/crates/stc_ts_file_analyzer/src/analyzer/expr/object.rs index 22e84097bc..eb88459bd5 100644 --- a/crates/stc_ts_file_analyzer/src/analyzer/expr/object.rs +++ b/crates/stc_ts_file_analyzer/src/analyzer/expr/object.rs @@ -1,4 +1,4 @@ -use std::{borrow::Cow, time::Instant}; +use std::borrow::Cow; use rnode::VisitMutWith; use stc_ts_ast_rnode::{RObjectLit, RPropOrSpread, RSpreadElement}; @@ -6,7 +6,7 @@ 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) { diff --git a/crates/stc_ts_file_analyzer/src/analyzer/generic/mod.rs b/crates/stc_ts_file_analyzer/src/analyzer/generic/mod.rs index 17c9398108..3e4309432e 100644 --- a/crates/stc_ts_file_analyzer/src/analyzer/generic/mod.rs +++ b/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::() ); - 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) } diff --git a/crates/stc_ts_file_analyzer/src/analyzer/scope/mod.rs b/crates/stc_ts_file_analyzer/src/analyzer/scope/mod.rs index cfeadbe21f..0b62af2660 100644 --- a/crates/stc_ts_file_analyzer/src/analyzer/scope/mod.rs +++ b/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,9 +2708,8 @@ impl Fold 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(); @@ -2717,7 +2717,7 @@ impl Fold for Expander<'_, '_, '_> { debug!( "[expander (time = {:?})]: {} => {}", - end - start, + timer.elapsed(), before, dump_type_as_string(&expanded) ); diff --git a/crates/stc_ts_file_analyzer/src/analyzer/stmt/mod.rs b/crates/stc_ts_file_analyzer/src/analyzer/stmt/mod.rs index ac744d1587..2c4102d221 100644 --- a/crates/stc_ts_file_analyzer/src/analyzer/stmt/mod.rs +++ b/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(()) diff --git a/crates/stc_ts_file_analyzer/src/env.rs b/crates/stc_ts_file_analyzer/src/env.rs index 32eb86b2dd..5eeb37889f 100644 --- a/crates/stc_ts_file_analyzer/src/env.rs +++ b/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) } } diff --git a/crates/stc_ts_type_checker/src/lib.rs b/crates/stc_ts_type_checker/src/lib.rs index 0adc5455a4..d9f056171d 100644 --- a/crates/stc_ts_type_checker/src/lib.rs +++ b/crates/stc_ts_type_checker/src/lib.rs @@ -1,6 +1,6 @@ //! Full type checker with dependency support. -use std::{mem::take, sync::Arc, time::Instant}; +use std::{mem::take, sync::Arc}; use dashmap::{DashMap, DashSet, SharedValue}; use fxhash::{FxBuildHasher, FxHashMap}; @@ -15,7 +15,7 @@ use stc_ts_errors::{debug::debugger::Debugger, Error}; use stc_ts_file_analyzer::{analyzer::Analyzer, loader::Load, validator::ValidateWith, ModuleTypeData, VResult}; use stc_ts_storage::{ErrorStore, File, Group, Single}; use stc_ts_types::{ModuleId, Type}; -use stc_utils::{cache::Freeze, early_error}; +use stc_utils::{cache::Freeze, early_error, perf_timer::PerfTimer}; use swc_atoms::JsWord; use swc_common::{errors::Handler, FileName, SourceMap, Spanned, DUMMY_SP}; use swc_ecma_ast::Module; @@ -89,19 +89,16 @@ impl Checker { /// After calling this method, you can get errors using `.take_errors()` pub fn check(&self, entry: Arc) -> ModuleId { - let start = Instant::now(); + let timer = PerfTimer::tracing_debug(); let modules = self.module_loader.load_module(&entry, true).expect("failed to load entry"); - let end = Instant::now(); - log::debug!("Loading of `{}` and dependencies took {:?}", entry, end - start); - - let start = Instant::now(); + timer.log(&format!("Loading of `{}` and dependencies", entry)); + let timer = PerfTimer::tracing_debug(); self.analyze_module(None, entry.clone()); - let end = Instant::now(); - log::debug!("Analysis of `{}` and dependencies took {:?}", entry, end - start); + timer.log(&format!("Analysis of `{}` and dependencies", entry)); modules.entry.id } @@ -236,7 +233,7 @@ impl Checker { } { - let start = Instant::now(); + let timer = PerfTimer::noop(); let mut did_work = false; let v = self.module_types.read().get(&id).cloned().unwrap(); // We now wait for dependency without holding lock @@ -248,9 +245,8 @@ impl Checker { }) .clone(); - let dur = Instant::now() - start; if !did_work { - log::warn!("Waited for {}: {:?}", path, dur); + log::warn!("Waited for {}: {:?}", path, timer.elapsed()); } res @@ -258,7 +254,7 @@ impl Checker { } fn analyze_non_circular_module(&self, module_id: ModuleId, path: Arc) -> Type { - let start = Instant::now(); + let timer = PerfTimer::log_trace(); let is_dts = match &*path { FileName::Real(path) => path.to_string_lossy().ends_with(".d.ts"), @@ -287,7 +283,7 @@ impl Checker { }; let mut mutations; { - let start = Instant::now(); + let timer = PerfTimer::log_debug(); let mut a = Analyzer::root( self.env.clone(), self.cm.clone(), @@ -299,9 +295,7 @@ impl Checker { module.visit_with(&mut a); - let end = Instant::now(); - let dur = end - start; - log::debug!("[Timing] Analysis of {} took {:?}", path, dur); + timer.log(&format!("[Timing] Analysis of {}", path)); mutations = a.mutations.unwrap(); } @@ -336,8 +330,7 @@ impl Checker { self.dts_modules.insert(module_id, module); - let dur = Instant::now() - start; - log::trace!("[Timing] Full analysis of {} took {:?}", path, dur); + timer.log(&format!("[Timing] Full analysis of {}", path)); type_info } diff --git a/crates/stc_ts_type_checker/src/typings.rs b/crates/stc_ts_type_checker/src/typings.rs index 7a37a3f648..1d036e6f4e 100644 --- a/crates/stc_ts_type_checker/src/typings.rs +++ b/crates/stc_ts_type_checker/src/typings.rs @@ -2,11 +2,11 @@ use std::{ fs::read_dir, path::{Path, PathBuf}, sync::Arc, - time::Instant, }; use rayon::prelude::*; use stc_ts_module_loader::resolvers::node::NodeResolver; +use stc_utils::perf_timer::PerfTimer; use swc_common::FileName; use crate::Checker; @@ -23,12 +23,11 @@ impl Checker { if let Ok(entry) = result { let entry = Arc::new(FileName::Real(entry)); - let start = Instant::now(); + let timer = PerfTimer::log_debug(); self.analyze_module(None, entry); - let end = Instant::now(); - log::debug!("Loading typings at `{}` took {:?}", dir.display(), end - start); + timer.log(&format!("Loading typings at `{}`", dir.display())); } } diff --git a/crates/stc_utils/Cargo.toml b/crates/stc_utils/Cargo.toml index 55e8aab869..b2d311be79 100644 --- a/crates/stc_utils/Cargo.toml +++ b/crates/stc_utils/Cargo.toml @@ -9,6 +9,7 @@ version = "0.1.0" [dependencies] ahash = "0.7.2" +log = "0.4.14" once_cell = "1" rustc-hash = "1.1.0" scoped-tls = "1.0.0" diff --git a/crates/stc_utils/src/lib.rs b/crates/stc_utils/src/lib.rs index 3406c6d6ae..d8436846c0 100644 --- a/crates/stc_utils/src/lib.rs +++ b/crates/stc_utils/src/lib.rs @@ -18,6 +18,7 @@ pub mod cache; pub mod error; pub mod ext; pub mod panic_context; +pub mod perf_timer; pub mod stack; pub type ABuilderHasher = ahash::RandomState; diff --git a/crates/stc_utils/src/perf_timer.rs b/crates/stc_utils/src/perf_timer.rs new file mode 100644 index 0000000000..d518033c31 --- /dev/null +++ b/crates/stc_utils/src/perf_timer.rs @@ -0,0 +1,81 @@ +use std::time::{Duration, Instant}; + +pub struct PerfTimer<'l> { + pub start: Instant, + pub logger: &'l dyn Fn(&str, Duration), +} + +impl<'l> PerfTimer<'l> { + pub fn with_logger(logger: &'l dyn Fn(&str, Duration)) -> Self { + Self { + start: Instant::now(), + logger, + } + } + + pub fn noop() -> Self { + Self::with_logger(&|_, _| {}) + } + + pub fn log_trace() -> Self { + Self::with_logger(&loggers::log_trace) + } + + pub fn log_debug() -> Self { + Self::with_logger(&loggers::log_debug) + } + + pub fn log_info() -> Self { + Self::with_logger(&loggers::log_info) + } + + pub fn log_warn() -> Self { + Self::with_logger(&loggers::log_warn) + } + + pub fn tracing_debug() -> Self { + Self::with_logger(&loggers::tracing_debug) + } + + pub fn tracing_warn() -> Self { + Self::with_logger(&loggers::tracing_warn) + } +} + +impl<'l> PerfTimer<'l> { + pub fn elapsed(&self) -> Duration { + self.start.elapsed() + } + + pub fn log(&self, scope: &str) { + (self.logger)(scope, self.start.elapsed()) + } +} + +mod loggers { + use std::time::Duration; + + pub fn log_trace(scope: &str, duration: Duration) { + log::trace!("{} took {:?}", scope, duration); + } + + pub fn log_debug(scope: &str, duration: Duration) { + log::debug!("{} took {:?}", scope, duration); + } + + pub fn log_info(scope: &str, duration: Duration) { + log::info!("{} took {:?}", scope, duration); + } + + pub fn log_warn(scope: &str, duration: Duration) { + log::warn!("{} took {:?}", scope, duration); + } + + pub fn tracing_debug(scope: &str, duration: Duration) { + tracing::debug!("{} took {:?}", scope, duration); + } + + pub fn tracing_warn(scope: &str, duration: Duration) { + tracing::warn!("{} took {:?}", scope, duration); + } +}