[heft] feat: add new task-level timing metrics

README.md

@@ -165,6 +165,7 @@ These GitHub repositories provide supplementary resources for Rush Stack:
 | [/build-tests/eslint-bulk-suppressions-test-legacy](./build-tests/eslint-bulk-suppressions-test-legacy/) | Sample code to test eslint bulk suppressions for versions of eslint < 8.57.0 |
 | [/build-tests/hashed-folder-copy-plugin-webpack5-test](./build-tests/hashed-folder-copy-plugin-webpack5-test/) | Building this project exercises @rushstack/hashed-folder-copy-plugin with Webpack 5. NOTE - THIS TEST IS CURRENTLY EXPECTED TO BE BROKEN |
 | [/build-tests/heft-copy-files-test](./build-tests/heft-copy-files-test/) | Building this project tests copying files with Heft |
+| [/build-tests/heft-example-lifecycle-plugin](./build-tests/heft-example-lifecycle-plugin/) | This is an example heft plugin for testing the lifecycle hooks |
 | [/build-tests/heft-example-plugin-01](./build-tests/heft-example-plugin-01/) | This is an example heft plugin that exposes hooks for other plugins |
 | [/build-tests/heft-example-plugin-02](./build-tests/heft-example-plugin-02/) | This is an example heft plugin that taps the hooks exposed from heft-example-plugin-01 |
 | [/build-tests/heft-fastify-test](./build-tests/heft-fastify-test/) | This project tests Heft support for the Fastify framework for Node.js services |

apps/heft/src/cli/HeftActionRunner.ts

@@ -403,14 +403,19 @@ export class HeftActionRunner {
 
       // Create operations for each task
       for (const task of phase.tasks) {
-        const taskOperation: Operation = _getOrCreateTaskOperation(internalHeftSession, task, operations);
+        const taskOperation: Operation = _getOrCreateTaskOperation(
+          internalHeftSession,
+          this._metricsCollector,
+          task,
+          operations
+        );
         // Set the phase operation as a dependency of the task operation to ensure the phase operation runs first
         taskOperation.addDependency(phaseOperation);
 
         // Set all dependency tasks as dependencies of the task operation
         for (const dependencyTask of task.dependencyTasks) {
           taskOperation.addDependency(
-            _getOrCreateTaskOperation(internalHeftSession, dependencyTask, operations)
+            _getOrCreateTaskOperation(internalHeftSession, this._metricsCollector, dependencyTask, operations)
           );
         }
 
@@ -459,6 +464,7 @@ function _getOrCreatePhaseOperation(
 function _getOrCreateTaskOperation(
   this: void,
   internalHeftSession: InternalHeftSession,
+  metricsCollector: MetricsCollector,
   task: HeftTask,
   operations: Map<string, Operation>
 ): Operation {
@@ -469,6 +475,7 @@ function _getOrCreateTaskOperation(
     operation = new Operation({
       groupName: task.parentPhase.phaseName,
       runner: new TaskOperationRunner({
+        metricsCollector,
         internalHeftSession,
         task
       })

apps/heft/src/index.ts

@@ -63,7 +63,9 @@ export {
   type IHeftRecordMetricsHookOptions,
   type IMetricsData,
   type IPerformanceData as _IPerformanceData,
-  MetricsCollector as _MetricsCollector
+  MetricsCollector as _MetricsCollector,
+  type IHeftTaskRecordMetricsHookOptions,
+  type ITaskMetricsData
 } from './metrics/MetricsCollector';
 
 export type { IScopedLogger } from './pluginFramework/logging/ScopedLogger';

apps/heft/src/metrics/MetricsCollector.ts

@@ -6,6 +6,31 @@ import { AsyncParallelHook } from 'tapable';
 import { performance } from 'perf_hooks';
 import { InternalError } from '@rushstack/node-core-library';
 
+/**
+ * @public
+ */
+export interface ITaskMetricsData {
+  /**
+   * The name of the task that was executed.
+   */
+  taskName: string;
+
+  /**
+   * The name of the phase that the task belongs to.
+   */
+  phaseName: string;
+
+  /**
+   * The total execution duration of the task, in milliseconds.
+   */
+  taskTotalExecutionMs: number;
+
+  /**
+   * Whether or not the task encountered errors.
+   */
+  encounteredError?: boolean;
+}
+
 /**
  * @public
  */
@@ -73,7 +98,7 @@ export interface IMetricsData {
 /**
  * @public
  */
-export interface IHeftRecordMetricsHookOptions {
+export interface IRecordMetricsHookOptions<T> {
   /**
    * @public
    */
@@ -82,11 +107,21 @@ export interface IHeftRecordMetricsHookOptions {
   /**
    * @public
    */
-  metricData: IMetricsData;
+  metricData: T;
 }
 
 /**
- * @internal
+ * @public
+ */
+export type IHeftRecordMetricsHookOptions = IRecordMetricsHookOptions<IMetricsData>;
+
+/**
+ * @public
+ */
+export type IHeftTaskRecordMetricsHookOptions = IRecordMetricsHookOptions<ITaskMetricsData>;
+
+/**
+ * @public
  */
 export interface IPerformanceData {
   taskTotalExecutionMs: number;
@@ -101,6 +136,9 @@ export class MetricsCollector {
   public readonly recordMetricsHook: AsyncParallelHook<IHeftRecordMetricsHookOptions> =
     new AsyncParallelHook<IHeftRecordMetricsHookOptions>(['recordMetricsHookOptions']);
 
+  public readonly recordTaskMetricsHook: AsyncParallelHook<IHeftTaskRecordMetricsHookOptions> =
+    new AsyncParallelHook<IHeftTaskRecordMetricsHookOptions>(['recordTaskMetricsHookOptions']);
+
   private _bootDurationMs: number | undefined;
   private _startTimeMs: number | undefined;
 
@@ -166,4 +204,49 @@ export class MetricsCollector {
       metricData
     });
   }
+
+  /**
+   * Record metrics to the installed plugin(s).
+   *
+   * @param command - Describe the user command, e.g. `start` or `build`
+   * @param parameterMap - Optional map of parameters to their values
+   * @param performanceData - Optional performance data
+   */
+  public async recordTaskAsync(
+    taskName: string,
+    phaseName: string,
+    performanceData?: Partial<IPerformanceData>
+  ): Promise<void> {
+    const { _bootDurationMs, _startTimeMs } = this;
+    if (_bootDurationMs === undefined || _startTimeMs === undefined) {
+      throw new InternalError('MetricsCollector has not been initialized with setStartTime() yet');
+    }
+
+    if (!taskName) {
+      throw new InternalError('The task name must be specified.');
+    }
+
+    if (!phaseName) {
+      throw new InternalError('The phase name must be specified.');
+    }
+
+    const filledPerformanceData: IPerformanceData = {
+      taskTotalExecutionMs: performance.now() - _startTimeMs,
+      ...(performanceData || {})
+    };
+
+    const { taskTotalExecutionMs } = filledPerformanceData;
+
+    const metricData: ITaskMetricsData = {
+      taskName: taskName,
+      phaseName: phaseName,
+      encounteredError: filledPerformanceData.encounteredError,
+      taskTotalExecutionMs: taskTotalExecutionMs
+    };
+
+    await this.recordTaskMetricsHook.promise({
+      metricName: 'task_execution_heft',
+      metricData
+    });
+  }
 }

apps/heft/src/operations/runners/TaskOperationRunner.ts

@@ -34,29 +34,12 @@ import {
   type IWatchFileSystem,
   WatchFileSystemAdapter
 } from '../../utilities/WatchFileSystemAdapter';
+import type { MetricsCollector } from '../../metrics/MetricsCollector';
 
 export interface ITaskOperationRunnerOptions {
   internalHeftSession: InternalHeftSession;
   task: HeftTask;
-}
-
-/**
- * Log out a start message, run a provided function, and log out an end message
- */
-export async function runAndMeasureAsync<T = void>(
-  fn: () => Promise<T>,
-  startMessageFn: () => string,
-  endMessageFn: () => string,
-  logFn: (message: string) => void
-): Promise<T> {
-  logFn(startMessageFn());
-  const startTime: number = performance.now();
-  try {
-    return await fn();
-  } finally {
-    const endTime: number = performance.now();
-    logFn(`${endMessageFn()} (${endTime - startTime}ms)`);
-  }
+  metricsCollector: MetricsCollector;
 }
 
 export class TaskOperationRunner implements IOperationRunner {
@@ -89,8 +72,9 @@ export class TaskOperationRunner implements IOperationRunner {
     context: IOperationRunnerContext,
     taskSession: HeftTaskSession
   ): Promise<OperationStatus> {
+    const { metricsCollector } = this._options;
     const { abortSignal, requestRun } = context;
-    const { hooks, logger } = taskSession;
+    const { hooks, logger, taskName, phaseName } = taskSession;
 
     // Need to clear any errors or warnings from the previous invocation, particularly
     // if this is an immediate rerun
@@ -155,61 +139,70 @@ export class TaskOperationRunner implements IOperationRunner {
       return OperationStatus.NoOp;
     }
 
-    const runResult: OperationStatus = shouldRun
-      ? await runAndMeasureAsync(
-          async (): Promise<OperationStatus> => {
-            // Create the options and provide a utility method to obtain paths to copy
-            const runHookOptions: IHeftTaskRunHookOptions = {
-              abortSignal,
-              globAsync: glob
+    let runResult: OperationStatus = OperationStatus.Success;
+    if (shouldRun) {
+      const runTaskAsync = async (): Promise<OperationStatus> => {
+        // Create the options and provide a utility method to obtain paths to copy
+        const runHookOptions: IHeftTaskRunHookOptions = {
+          abortSignal,
+          globAsync: glob
+        };
+
+        // Run the plugin run hook
+        try {
+          if (shouldRunIncremental) {
+            const runIncrementalHookOptions: IHeftTaskRunIncrementalHookOptions = {
+              ...runHookOptions,
+              watchGlobAsync: (
+                pattern: string | string[],
+                options: IGlobOptions = {}
+              ): Promise<Map<string, IWatchedFileState>> => {
+                return watchGlobAsync(pattern, {
+                  ...options,
+                  fs: getWatchFileSystemAdapter()
+                });
+              },
+              get watchFs(): IWatchFileSystem {
+                return getWatchFileSystemAdapter();
+              },
+              requestRun: requestRun!
             };
+            await hooks.runIncremental.promise(runIncrementalHookOptions);
+          } else {
+            await hooks.run.promise(runHookOptions);
+          }
+        } catch (e) {
+          // Log out using the task logger, and return an error status
+          if (!(e instanceof AlreadyReportedError)) {
+            logger.emitError(e as Error);
+          }
+          return OperationStatus.Failure;
+        }
 
-            // Run the plugin run hook
-            try {
-              if (shouldRunIncremental) {
-                const runIncrementalHookOptions: IHeftTaskRunIncrementalHookOptions = {
-                  ...runHookOptions,
-                  watchGlobAsync: (
-                    pattern: string | string[],
-                    options: IGlobOptions = {}
-                  ): Promise<Map<string, IWatchedFileState>> => {
-                    return watchGlobAsync(pattern, {
-                      ...options,
-                      fs: getWatchFileSystemAdapter()
-                    });
-                  },
-                  get watchFs(): IWatchFileSystem {
-                    return getWatchFileSystemAdapter();
-                  },
-                  requestRun: requestRun!
-                };
-                await hooks.runIncremental.promise(runIncrementalHookOptions);
-              } else {
-                await hooks.run.promise(runHookOptions);
-              }
-            } catch (e) {
-              // Log out using the task logger, and return an error status
-              if (!(e instanceof AlreadyReportedError)) {
-                logger.emitError(e as Error);
-              }
-              return OperationStatus.Failure;
-            }
-
-            if (abortSignal.aborted) {
-              return OperationStatus.Aborted;
-            }
-
-            return OperationStatus.Success;
-          },
-          () => `Starting ${shouldRunIncremental ? 'incremental ' : ''}task execution`,
-          () => {
-            const finishedWord: string = abortSignal.aborted ? 'Aborted' : 'Finished';
-            return `${finishedWord} ${shouldRunIncremental ? 'incremental ' : ''}task execution`;
-          },
-          terminal.writeVerboseLine.bind(terminal)
-        )
-      : // This branch only occurs if only file operations are defined.
-        OperationStatus.Success;
+        if (abortSignal.aborted) {
+          return OperationStatus.Aborted;
+        }
+
+        return OperationStatus.Success;
+      };
+
+      const startTime: number = performance.now();
+      terminal.writeVerboseLine(`Starting ${shouldRunIncremental ? 'incremental ' : ''}task execution`);
+      try {
+        runResult = await runTaskAsync();
+      } finally {
+        const endTime: number = performance.now();
+        const finishedWord: string = abortSignal.aborted ? 'Aborted' : 'Finished';
+        terminal.writeVerboseLine(
+          `${finishedWord} ${shouldRunIncremental ? 'incremental ' : ''}task execution (${
+            endTime - startTime
+          }ms)`
+        );
+        await metricsCollector.recordTaskAsync(taskName, phaseName, {
+          taskTotalExecutionMs: endTime - startTime
+        });
+      }
+    }
 
     if (this._fileOperations) {
       const { copyOperations, deleteOperations } = this._fileOperations;

apps/heft/src/pluginFramework/HeftLifecycle.ts

@@ -67,7 +67,8 @@ export class HeftLifecycle extends HeftPluginHost {
       clean: new AsyncParallelHook<IHeftLifecycleCleanHookOptions>(),
       toolStart: new AsyncParallelHook<IHeftLifecycleToolStartHookOptions>(),
       toolFinish: new AsyncParallelHook<IHeftLifecycleToolFinishHookOptions>(),
-      recordMetrics: internalHeftSession.metricsCollector.recordMetricsHook
+      recordMetrics: internalHeftSession.metricsCollector.recordMetricsHook,
+      recordTaskMetrics: internalHeftSession.metricsCollector.recordTaskMetricsHook
     };
   }
 

apps/heft/src/pluginFramework/HeftLifecycleSession.ts

@@ -4,7 +4,11 @@
 import * as path from 'path';
 import type { AsyncParallelHook } from 'tapable';
 
-import type { IHeftRecordMetricsHookOptions, MetricsCollector } from '../metrics/MetricsCollector';
+import type {
+  IHeftRecordMetricsHookOptions,
+  IHeftTaskRecordMetricsHookOptions,
+  MetricsCollector
+} from '../metrics/MetricsCollector';
 import type { ScopedLogger, IScopedLogger } from './logging/ScopedLogger';
 import type { IInternalHeftSessionOptions } from './InternalHeftSession';
 import type { IHeftParameters } from './HeftParameterManager';
@@ -111,6 +115,16 @@ export interface IHeftLifecycleHooks {
    * @public
    */
   recordMetrics: AsyncParallelHook<IHeftRecordMetricsHookOptions>;
+
+  /**
+   * The `recordTaskMetrics` hook is called at the end of every Heft task execution. It is called after all
+   * tasks have completed execution (or been canceled). In a watch run, it will be called several times
+   * in between `toolStart` and (if the session is gracefully interrupted via Ctrl+C), `toolFinish`.
+   * In a non-watch run, it will be invoked exactly once between `toolStart` and `toolFinish`.
+   *  To use it, call `recordMetrics.tapPromise(<pluginName>, <callback>)`.
+   * @public
+   */
+  recordTaskMetrics: AsyncParallelHook<IHeftTaskRecordMetricsHookOptions>;
 }
 
 /**