feat: add --verbose flag to expose stateless installation steps of Dataform Core and identify bottlenecks (#2100)

* feat: add --verbose argument to expose steps in stateless installation

* chore: make verbose and quiet flags mutually exclusive

* feat: use performance timing in node to avoid system clock issues

* chore: do not export print

* refactor: remove redundant double check

* chore: print should pipe to stderr

Author: ashish10alex

cli/api/commands/compile.ts

@@ -12,6 +12,10 @@ import { dataform } from "df/protos/ts";
 
 export class CompilationTimeoutError extends Error {}
 
+function print(text: string) {
+  process.stderr.write(text);
+}
+
 export async function compile(
   compileConfig: dataform.ICompileConfig = {}
 ): Promise<dataform.CompiledGraph> {
@@ -41,8 +45,19 @@ export async function compile(
       }
     });
 
+    if (compileConfig.verbose) {
+      print(`Using isolated environment for @dataform/core@${workflowSettingsDataformCoreVersion}\n`);
+      print(`Copying project to temporary directory: ${temporaryProjectPath}\n`);
+    }
+    const copyStartTime = performance.now();
     fs.copySync(resolvedProjectPath, temporaryProjectPath);
+    if (compileConfig.verbose) {
+      print(`Project copy completed in ${performance.now() - copyStartTime}ms\n`);
+    }
 
+    if (compileConfig.verbose) {
+      print(`Generating temporary package.json\n`);
+    }
     fs.writeFileSync(
       path.join(temporaryProjectPath, "package.json"),
       `{
@@ -52,9 +67,19 @@ export async function compile(
 }`
     );
 
-    await promisify(exec)("npm i --ignore-scripts", {
+    const npmCommand = `npm i --ignore-scripts${compileConfig.verbose ? " --loglevel=http" : ""}`;
+    if (compileConfig.verbose) {
+      print(`Running '${npmCommand}' in temporary directory...\n`);
+    }
+    const npmStartTime = performance.now();
+    const { stdout, stderr } = await promisify(exec)(npmCommand, {
       cwd: temporaryProjectPath
     });
+    
+    if (compileConfig.verbose) {
+      print(`NPM HTTP Logs:\n${stderr}\n`);
+      print(`NPM install completed in ${performance.now() - npmStartTime}ms\n`);
+    }
 
     compileConfig.projectDir = temporaryProjectPath;
   }
@@ -77,7 +102,7 @@ export class CompileChildProcess {
     // if it exists, otherwise run the bazel compile loader target.
     const findForkScript = () => {
       try {
-        const workerBundlePath = require.resolve("./worker_bundle");
+        const workerBundlePath = require.resolve("./worker_bundle.js");
         return workerBundlePath;
       } catch (e) {
         return require.resolve("../../vm/compile_loader");

cli/index.ts

@@ -213,6 +213,7 @@ const testConnectionOptionName = "test-connection";
 
 const watchOptionName = "watch";
 
+const verboseOptionName = "verbose";
 const dryRunOptionName = "dry-run";
 const runTestsOptionName = "run-tests";
 const checkOptionName = "check";
@@ -375,6 +376,19 @@ export function runCli() {
           jsonOutputOption,
           timeoutOption,
           quietCompileOption,
+          {
+            name: verboseOptionName,
+            option: {
+              describe: "Enable verbose compilation output. Example usage: 'dataform compile --verbose'",
+              type: "boolean",
+              default: false
+            },
+            check: (argv: yargs.Arguments) => {
+              if (argv.quiet && argv.verbose) {
+                throw new Error("Arguments --verbose and --quiet are mutually exclusive.");
+              }
+            }
+          },
           ...ProjectConfigOptions.allYargsOptions
         ],
         processFn: async argv => {
@@ -387,7 +401,8 @@ export function runCli() {
             const compiledGraph = await compile({
               projectDir,
               projectConfigOverride: ProjectConfigOptions.constructProjectConfigOverride(argv),
-              timeoutMillis: argv[timeoutOption.name] || undefined
+              timeoutMillis: argv[timeoutOption.name] || undefined,
+              verbose: argv[verboseOptionName] || false
             });
             printCompiledGraph(compiledGraph, argv[jsonOutputOption.name], argv[quietCompileOption.name]);
             if (compiledGraphHasErrors(compiledGraph)) {

protos/core.proto

@@ -51,6 +51,9 @@ message CompileConfig {
 
   Extension extension = 10;
 
+  // Whether to emit compilation debug logs.
+  bool verbose = 11;
+
   reserved 2, 4, 5, 7, 9;
 }