diff --git a/cli/fs.rs b/cli/fs.rs index 9b69c7e3ba..83dec49139 100644 --- a/cli/fs.rs +++ b/cli/fs.rs @@ -36,7 +36,6 @@ pub fn write_file_2>( { use std::os::unix::fs::PermissionsExt; let mode = mode & 0o777; - debug!("set file mode to {:o}", mode); let permissions = PermissionsExt::from_mode(mode); file.set_permissions(permissions)?; } diff --git a/cli/js/compiler.ts b/cli/js/compiler.ts index fa2c5fd414..d86109278a 100644 --- a/cli/js/compiler.ts +++ b/cli/js/compiler.ts @@ -434,12 +434,11 @@ class Host implements ts.CompilerHost { moduleNames, containingFile, }); - return moduleNames.map((specifier) => { + const resolved = moduleNames.map((specifier) => { const maybeUrl = SourceFile.getResolvedUrl(specifier, containingFile); log("compiler::host.resolveModuleNames maybeUrl", { specifier, - containingFile, maybeUrl, }); @@ -461,6 +460,8 @@ class Host implements ts.CompilerHost { extension: sourceFile.extension, }; }); + log(resolved); + return resolved; } useCaseSensitiveFileNames(): boolean { @@ -482,7 +483,7 @@ class Host implements ts.CompilerHost { // NOTE: target doesn't really matter here, // this is in fact a mock host created just to // load all type definitions and snapshot them. -const SNAPSHOT_HOST = new Host({ +let SNAPSHOT_HOST: Host | undefined = new Host({ target: CompilerHostTarget.Main, writeFile(): void {}, }); @@ -529,6 +530,9 @@ const _TS_SNAPSHOT_PROGRAM = ts.createProgram({ host: SNAPSHOT_HOST, }); +// Derference the snapshot host so it can be GCed +SNAPSHOT_HOST = undefined; + // This function is called only during snapshotting process const SYSTEM_LOADER = getAsset("system_loader.js"); const SYSTEM_LOADER_ES5 = getAsset("system_loader_es5.js"); @@ -843,6 +847,46 @@ const ignoredDiagnostics = [ 7016, ]; +type Stats = Array<{ key: string; value: number }>; + +const stats: Stats = []; +let statsStart = 0; + +function performanceStart(): void { + stats.length = 0; + // TODO(kitsonk) replace with performance.mark() when landed + statsStart = performance.now(); + ts.performance.enable(); +} + +function performanceProgram(program: ts.Program): void { + stats.push({ key: "Files", value: program.getSourceFiles().length }); + stats.push({ key: "Nodes", value: program.getNodeCount() }); + stats.push({ key: "Identifiers", value: program.getIdentifierCount() }); + stats.push({ key: "Symbols", value: program.getSymbolCount() }); + stats.push({ key: "Types", value: program.getTypeCount() }); + stats.push({ key: "Instantiations", value: program.getInstantiationCount() }); + const programTime = ts.performance.getDuration("Program"); + const bindTime = ts.performance.getDuration("Bind"); + const checkTime = ts.performance.getDuration("Check"); + const emitTime = ts.performance.getDuration("Emit"); + stats.push({ key: "Parse time", value: programTime }); + stats.push({ key: "Bind time", value: bindTime }); + stats.push({ key: "Check time", value: checkTime }); + stats.push({ key: "Emit time", value: emitTime }); + stats.push({ + key: "Total TS time", + value: programTime + bindTime + checkTime + emitTime, + }); +} + +function performanceEnd(): Stats { + // TODO(kitsonk) replace with performance.measure() when landed + const duration = performance.now() - statsStart; + stats.push({ key: "Compile time", value: duration }); + return stats; +} + // TODO(Bartlomieju): this check should be done in Rust; there should be no // console.log here function processConfigureResponse( @@ -1073,6 +1117,7 @@ interface CompileRequest { configPath?: string; config?: string; unstable: boolean; + performance: boolean; cwd: string; // key value is fully resolved URL sourceFileMap: Record; @@ -1086,6 +1131,7 @@ interface BundleRequest { configPath?: string; config?: string; unstable: boolean; + performance: boolean; cwd: string; // key value is fully resolved URL sourceFileMap: Record; @@ -1128,11 +1174,13 @@ type CompilerRequest = interface CompileResponse { emitMap: Record; diagnostics: Diagnostic; + stats?: Stats; } interface BundleResponse { bundleOutput?: string; diagnostics: Diagnostic; + stats?: Stats; } interface RuntimeCompileResponse { @@ -1145,21 +1193,22 @@ interface RuntimeBundleResponse { diagnostics: DiagnosticItem[]; } -function compile(request: CompileRequest): CompileResponse { - const { - allowJs, - config, - configPath, - rootNames, - target, - unstable, - cwd, - sourceFileMap, - } = request; - log(">>> compile start", { - rootNames, - type: CompilerRequestType[request.type], - }); +function compile({ + allowJs, + config, + configPath, + rootNames, + target, + unstable, + performance, + cwd, + sourceFileMap, + type, +}: CompileRequest): CompileResponse { + if (performance) { + performanceStart(); + } + log(">>> compile start", { rootNames, type: CompilerRequestType[type] }); // When a programme is emitted, TypeScript will call `writeFile` with // each file that needs to be emitted. The Deno compiler host delegates @@ -1216,32 +1265,38 @@ function compile(request: CompileRequest): CompileResponse { // without casting. diagnostics = emitResult.diagnostics; } + if (performance) { + performanceProgram(program); + } } - log("<<< compile end", { - rootNames, - type: CompilerRequestType[request.type], - }); + log("<<< compile end", { rootNames, type: CompilerRequestType[type] }); + const stats = performance ? performanceEnd() : undefined; return { emitMap: state.emitMap, diagnostics: fromTypeScriptDiagnostic(diagnostics), + stats, }; } -function bundle(request: BundleRequest): BundleResponse { - const { - config, - configPath, - rootNames, - target, - unstable, - cwd, - sourceFileMap, - } = request; +function bundle({ + type, + config, + configPath, + rootNames, + target, + unstable, + performance, + cwd, + sourceFileMap, +}: BundleRequest): BundleResponse { + if (performance) { + performanceStart(); + } log(">>> start start", { rootNames, - type: CompilerRequestType[request.type], + type: CompilerRequestType[type], }); // When a programme is emitted, TypeScript will call `writeFile` with @@ -1293,6 +1348,9 @@ function bundle(request: BundleRequest): BundleResponse { // without casting. diagnostics = emitResult.diagnostics; } + if (performance) { + performanceProgram(program); + } } let bundleOutput; @@ -1302,14 +1360,17 @@ function bundle(request: BundleRequest): BundleResponse { bundleOutput = state.bundleOutput; } + const stats = performance ? performanceEnd() : undefined; + const result: BundleResponse = { bundleOutput, diagnostics: fromTypeScriptDiagnostic(diagnostics), + stats, }; log("<<< bundle end", { rootNames, - type: CompilerRequestType[request.type], + type: CompilerRequestType[type], }); return result; @@ -1492,27 +1553,27 @@ async function tsCompilerOnMessage({ }): Promise { switch (request.type) { case CompilerRequestType.Compile: { - const result = compile(request as CompileRequest); + const result = compile(request); globalThis.postMessage(result); break; } case CompilerRequestType.Bundle: { - const result = bundle(request as BundleRequest); + const result = bundle(request); globalThis.postMessage(result); break; } case CompilerRequestType.RuntimeCompile: { - const result = runtimeCompile(request as RuntimeCompileRequest); + const result = runtimeCompile(request); globalThis.postMessage(result); break; } case CompilerRequestType.RuntimeBundle: { - const result = runtimeBundle(request as RuntimeBundleRequest); + const result = runtimeBundle(request); globalThis.postMessage(result); break; } case CompilerRequestType.RuntimeTranspile: { - const result = await runtimeTranspile(request as RuntimeTranspileRequest); + const result = await runtimeTranspile(request); globalThis.postMessage(result); break; } diff --git a/cli/js/ts_global.d.ts b/cli/js/ts_global.d.ts index bca602998d..dcdf4a3e46 100644 --- a/cli/js/ts_global.d.ts +++ b/cli/js/ts_global.d.ts @@ -24,5 +24,10 @@ declare global { // there is a risk these could change in future versions of TypeScript export const libs: string[]; export const libMap: Map; + export const performance: { + enable(): void; + disable(): void; + getDuration(value: string): number; + }; } } diff --git a/cli/main.rs b/cli/main.rs index c94aed2444..e20435a007 100644 --- a/cli/main.rs +++ b/cli/main.rs @@ -428,7 +428,11 @@ async fn bundle_command( let global_state = GlobalState::new(flags)?; - info!("Bundling {}", module_specifier.to_string()); + info!( + "{} {}", + colors::green("Bundle".to_string()), + module_specifier.to_string() + ); let output = tsc::bundle( &global_state, @@ -442,11 +446,15 @@ async fn bundle_command( debug!(">>>>> bundle END"); if let Some(out_file_) = out_file.as_ref() { - info!("Emitting bundle to {:?}", out_file_); let output_bytes = output.as_bytes(); let output_len = output_bytes.len(); deno_fs::write_file(out_file_, output_bytes, 0o666)?; - info!("{} emitted.", human_size(output_len as f64)); + info!( + "{} {:?} ({})", + colors::green("Emit".to_string()), + out_file_, + colors::gray(human_size(output_len as f64)) + ); } else { println!("{}", output); } diff --git a/cli/tests/integration_tests.rs b/cli/tests/integration_tests.rs index 78a89eb2b8..d5b4016c16 100644 --- a/cli/tests/integration_tests.rs +++ b/cli/tests/integration_tests.rs @@ -2048,6 +2048,11 @@ itest!(single_compile_with_reload { output: "single_compile_with_reload.ts.out", }); +itest!(performance_stats { + args: "run --reload --log-level debug 002_hello.ts", + output: "performance_stats.out", +}); + itest!(proto_exploit { args: "run proto_exploit.js", output: "proto_exploit.js.out", diff --git a/cli/tests/performance_stats.out b/cli/tests/performance_stats.out new file mode 100644 index 0000000000..9fea7715ad --- /dev/null +++ b/cli/tests/performance_stats.out @@ -0,0 +1,14 @@ +[WILDCARD] +Files: 43 +Nodes: [WILDCARD] +Identifiers: [WILDCARD] +Symbols: [WILDCARD] +Types: [WILDCARD] +Instantiations: [WILDCARD] +Parse time: [WILDCARD] +Bind time: [WILDCARD] +Check time: [WILDCARD] +Emit time: [WILDCARD] +Total TS time: [WILDCARD] +Compile time: [WILDCARD] +[WILDCARD] diff --git a/cli/tsc.rs b/cli/tsc.rs index c1b15bbf0b..bb65449618 100644 --- a/cli/tsc.rs +++ b/cli/tsc.rs @@ -34,7 +34,9 @@ use deno_core::StartupData; use futures::future::Either; use futures::future::Future; use futures::future::FutureExt; +use log::debug; use log::info; +use log::Level; use regex::Regex; use serde::Deserialize; use serde::Serialize; @@ -332,6 +334,15 @@ pub fn source_code_version_hash( crate::checksum::gen(vec![source_code, version.as_bytes(), config_hash]) } +fn maybe_log_stats(maybe_stats: Option>) { + if let Some(stats) = maybe_stats { + debug!("DEBUG - Compilation Statistics:"); + for stat in stats { + debug!("{}: {}", stat.key, stat.value); + } + } +} + pub struct TsCompilerInner { pub file_fetcher: SourceFileFetcher, pub config: CompilerConfig, @@ -356,6 +367,13 @@ impl Deref for TsCompiler { } } +#[derive(Deserialize)] +#[serde(rename_all = "camelCase")] +struct Stat { + key: String, + value: f64, +} + #[derive(Deserialize)] #[serde(rename_all = "camelCase")] struct EmittedSource { @@ -368,6 +386,7 @@ struct EmittedSource { struct BundleResponse { diagnostics: Diagnostic, bundle_output: Option, + stats: Option>, } #[derive(Deserialize)] @@ -375,6 +394,7 @@ struct BundleResponse { struct CompileResponse { diagnostics: Diagnostic, emit_map: HashMap, + stats: Option>, } // TODO(bartlomieju): possible deduplicate once TS refactor is stabilized @@ -509,6 +529,10 @@ impl TsCompiler { }; let root_names = vec![module_url.to_string()]; let unstable = global_state.flags.unstable; + let performance = match global_state.flags.log_level { + Some(Level::Debug) => true, + _ => false, + }; let compiler_config = self.config.clone(); let cwd = std::env::current_dir().unwrap(); let j = match (compiler_config.path, compiler_config.content) { @@ -518,6 +542,7 @@ impl TsCompiler { "target": target, "rootNames": root_names, "unstable": unstable, + "performance": performance, "configPath": config_path, "config": str::from_utf8(&config_data).unwrap(), "cwd": cwd, @@ -529,6 +554,7 @@ impl TsCompiler { "target": target, "rootNames": root_names, "unstable": unstable, + "performance": performance, "cwd": cwd, "sourceFileMap": module_graph_json, }), @@ -555,6 +581,8 @@ impl TsCompiler { return Err(ErrBox::from(compile_response.diagnostics)); } + maybe_log_stats(compile_response.stats); + self.set_graph_metadata( source_file.url.clone(), &compile_response.emit_map, @@ -949,6 +977,10 @@ pub async fn bundle( let root_names = vec![module_specifier.to_string()]; let target = "main"; let cwd = std::env::current_dir().unwrap(); + let performance = match global_state.flags.log_level { + Some(Level::Debug) => true, + _ => false, + }; // TODO(bartlomieju): this is non-sense; CompilerConfig's `path` and `content` should // be optional @@ -958,6 +990,7 @@ pub async fn bundle( "target": target, "rootNames": root_names, "unstable": unstable, + "performance": performance, "configPath": config_path, "config": str::from_utf8(&config_data).unwrap(), "cwd": cwd, @@ -968,6 +1001,7 @@ pub async fn bundle( "target": target, "rootNames": root_names, "unstable": unstable, + "performance": performance, "cwd": cwd, "sourceFileMap": module_graph_json, }), @@ -978,10 +1012,11 @@ pub async fn bundle( let msg = execute_in_same_thread(global_state.clone(), permissions, req_msg).await?; let json_str = std::str::from_utf8(&msg).unwrap(); - debug!("Message: {}", json_str); let bundle_response: BundleResponse = serde_json::from_str(json_str)?; + maybe_log_stats(bundle_response.stats); + if !bundle_response.diagnostics.items.is_empty() { return Err(ErrBox::from(bundle_response.diagnostics)); }