refactor(ngcc): add debug logging for the duration of different operations (#32427)

This gives an overview of how much time is spent in each operation/phase
and makes it easy to do rough comparisons of how different
configurations or changes affect performance.

PR Close #32427

packages/compiler-cli/ngcc/main-ngcc.ts

@@ -14,6 +14,8 @@ import {ConsoleLogger, LogLevel} from './src/logging/console_logger';
 
 // CLI entry point
 if (require.main === module) {
+  const startTime = Date.now();
+
   const args = process.argv.slice(2);
   const options =
       yargs
@@ -67,14 +69,22 @@ if (require.main === module) {
 
   (async() => {
     try {
+      const logger = logLevel && new ConsoleLogger(LogLevel[logLevel]);
+
       await mainNgcc({
         basePath: baseSourcePath,
         propertiesToConsider,
         targetEntryPointPath,
         compileAllFormats,
-        logger: logLevel && new ConsoleLogger(LogLevel[logLevel]),
+        logger,
         async: true,
       });
+
+      if (logger) {
+        const duration = Math.round((Date.now() - startTime) / 1000);
+        logger.debug(`Run ngcc in ${duration}s.`);
+      }
+
       process.exitCode = 0;
     } catch (e) {
       console.error(e.stack || e.message);

packages/compiler-cli/ngcc/src/execution/cluster/master.ts

@@ -26,6 +26,7 @@ import {Deferred, sendMessageToWorker} from './utils';
  */
 export class ClusterMaster {
   private finishedDeferred = new Deferred<void>();
+  private processingStartTime: number = -1;
   private taskAssignments = new Map<number, Task|null>();
   private taskQueue: TaskQueue;
 
@@ -67,6 +68,9 @@ export class ClusterMaster {
 
     // First, check whether all tasks have been completed.
     if (this.taskQueue.allTasksCompleted) {
+      const duration = Math.round((Date.now() - this.processingStartTime) / 1000);
+      this.logger.debug(`Processed tasks in ${duration}s.`);
+
       return this.finishedDeferred.resolve();
     }
 
@@ -176,6 +180,11 @@ export class ClusterMaster {
       throw new Error(`Invariant violated: Worker #${workerId} came online more than once.`);
     }
 
+    if (this.processingStartTime === -1) {
+      this.logger.debug('Processing tasks...');
+      this.processingStartTime = Date.now();
+    }
+
     this.taskAssignments.set(workerId, null);
     this.maybeDistributeWork();
   }

packages/compiler-cli/ngcc/src/execution/single_process_executor.ts

@@ -27,11 +27,17 @@ export class SingleProcessExecutor implements Executor {
         createCompileFn((task, outcome) => onTaskCompleted(this.pkgJsonUpdater, task, outcome));
 
     // Process all tasks.
+    this.logger.debug('Processing tasks...');
+    const startTime = Date.now();
+
     while (!taskQueue.allTasksCompleted) {
       const task = taskQueue.getNextTask() !;
       compile(task);
       taskQueue.markTaskCompleted(task);
     }
+
+    const duration = Math.round((Date.now() - startTime) / 1000);
+    this.logger.debug(`Processed tasks in ${duration}s.`);
   }
 }
 

packages/compiler-cli/ngcc/src/main.ts

@@ -141,6 +141,9 @@ export function mainNgcc(
 
   // The function for performing the analysis.
   const analyzeEntryPoints: AnalyzeEntryPointsFn = () => {
+    logger.debug('Analyzing entry-points...');
+    const startTime = Date.now();
+
     const supportedPropertiesToConsider = ensureSupportedProperties(propertiesToConsider);
 
     const moduleResolver = new ModuleResolver(fileSystem, pathMappings);
@@ -197,6 +200,11 @@ export function mainNgcc(
           unprocessableEntryPointPaths.map(path => `\n  - ${path}`).join(''));
     }
 
+    const duration = Math.round((Date.now() - startTime) / 1000);
+    logger.debug(
+        `Analyzed ${entryPoints.length} entry-points in ${duration}s. ` +
+        `(Total tasks: ${tasks.length})`);
+
     return getTaskQueue(inParallel, tasks, graph);
   };