Add ability to output compiler performance information (#6434)

cli/fs.rs

@@ -36,7 +36,6 @@ pub fn write_file_2<T: AsRef<[u8]>>(
     {
       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)?;
     }

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<string, SourceFileMapEntry>;
@@ -1086,6 +1131,7 @@ interface BundleRequest {
   configPath?: string;
   config?: string;
   unstable: boolean;
+  performance: boolean;
   cwd: string;
   // key value is fully resolved URL
   sourceFileMap: Record<string, SourceFileMapEntry>;
@@ -1128,11 +1174,13 @@ type CompilerRequest =
 interface CompileResponse {
   emitMap: Record<string, EmittedSource>;
   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 {
+function compile({
   allowJs,
   config,
   configPath,
   rootNames,
   target,
   unstable,
+  performance,
   cwd,
   sourceFileMap,
-  } = request;
-  log(">>> compile start", {
-    rootNames,
-    type: CompilerRequestType[request.type],
-  });
+  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 {
+function bundle({
+  type,
   config,
   configPath,
   rootNames,
   target,
   unstable,
+  performance,
   cwd,
   sourceFileMap,
-  } = request;
+}: 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<void> {
   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;
     }

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<string, string>;
+    export const performance: {
+      enable(): void;
+      disable(): void;
+      getDuration(value: string): number;
+    };
   }
 }

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);
   }

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",

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]

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<Vec<Stat>>) {
+  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<String>,
+  stats: Option<Vec<Stat>>,
 }
 
 #[derive(Deserialize)]
@@ -375,6 +394,7 @@ struct BundleResponse {
 struct CompileResponse {
   diagnostics: Diagnostic,
   emit_map: HashMap<String, EmittedSource>,
+  stats: Option<Vec<Stat>>,
 }
 
 // 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));
   }