Merge pull request #3649 from chengcyber/feat-operation-metadata

[rush] restore the duration of the same operation without cache hit as telemetry data

Author: iclanton

common/changes/@microsoft/rush/feat-operation-metadata_2022-09-26-12-16.json

@@ -0,0 +1,10 @@
+{
+  "changes": [
+    {
+      "packageName": "@microsoft/rush",
+      "comment": "Include the operation duration in the telemetry data that was recorded during the non-cached run when a cache hit occurs.",
+      "type": "none"
+    }
+  ],
+  "packageName": "@microsoft/rush"
+}

common/reviews/api/rush-lib.api.md

@@ -372,6 +372,7 @@ export interface _INpmOptionsJson extends IPackageManagerOptionsJsonBase {
 // @alpha
 export interface IOperationExecutionResult {
     readonly error: Error | undefined;
+    readonly nonCachedDurationMs: number | undefined;
     readonly status: OperationStatus;
     readonly stdioSummarizer: StdioSummarizer;
     readonly stopwatch: IStopwatchResult;
@@ -399,8 +400,25 @@ export interface IOperationRunner {
 export interface IOperationRunnerContext {
     collatedWriter: CollatedWriter;
     debugMode: boolean;
+    // @internal
+    _operationStateFile?: _OperationStateFile;
     quietMode: boolean;
     stdioSummarizer: StdioSummarizer;
+    stopwatch: IStopwatchResult;
+}
+
+// @internal (undocumented)
+export interface _IOperationStateFileOptions {
+    // (undocumented)
+    phase: IPhase;
+    // (undocumented)
+    rushProject: RushConfigurationProject;
+}
+
+// @internal (undocumented)
+export interface _IOperationStateJson {
+    // (undocumented)
+    nonCachedDurationMs: number;
 }
 
 // @public
@@ -471,7 +489,7 @@ export interface IRushSessionOptions {
     terminalProvider: ITerminalProvider;
 }
 
-// @alpha
+// @beta
 export interface IStopwatchResult {
     get duration(): number;
     get endTime(): number | undefined;
@@ -508,6 +526,7 @@ export interface ITelemetryMachineInfo {
 export interface ITelemetryOperationResult {
     dependencies: string[];
     endTimestampMs?: number;
+    nonCachedDurationMs?: number;
     result: string;
     startTimestampMs?: number;
 }
@@ -582,6 +601,19 @@ export class Operation {
     weight: number;
 }
 
+// @internal
+export class _OperationStateFile {
+    constructor(options: _IOperationStateFileOptions);
+    get filename(): string;
+    static getFilenameRelativeToProjectRoot(phase: IPhase): string;
+    // (undocumented)
+    get state(): _IOperationStateJson | undefined;
+    // (undocumented)
+    tryRestoreAsync(): Promise<_IOperationStateJson | undefined>;
+    // (undocumented)
+    writeAsync(json: _IOperationStateJson): Promise<void>;
+}
+
 // @beta
 export enum OperationStatus {
     Blocked = "BLOCKED",

libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts

@@ -578,6 +578,7 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
           operationResults[operation.name!] = {
             startTimestampMs: startTime,
             endTimestampMs: endTime,
+            nonCachedDurationMs: operationResult.nonCachedDurationMs,
             result: operationResult.status,
             dependencies: Array.from(getNonSilentDependencies(operation)).sort()
           };

libraries/rush-lib/src/index.ts

@@ -118,3 +118,8 @@ export { ICredentialCacheOptions, ICredentialCacheEntry, CredentialCache } from
 export type { ITelemetryData, ITelemetryMachineInfo, ITelemetryOperationResult } from './logic/Telemetry';
 
 export { IStopwatchResult } from './utilities/Stopwatch';
+export {
+  OperationStateFile as _OperationStateFile,
+  IOperationStateFileOptions as _IOperationStateFileOptions,
+  IOperationStateJson as _IOperationStateJson
+} from './logic/operations/OperationStateFile';

libraries/rush-lib/src/logic/Telemetry.ts

@@ -66,6 +66,11 @@ export interface ITelemetryOperationResult {
    * If the operation was blocked, will be `undefined`.
    */
   endTimestampMs?: number;
+
+  /**
+   * Duration in milliseconds when the operation does not hit cache
+   */
+  nonCachedDurationMs?: number;
 }
 
 /**

libraries/rush-lib/src/logic/buildCache/ProjectBuildCache.ts

@@ -3,7 +3,7 @@
 
 import * as path from 'path';
 import * as crypto from 'crypto';
-import { FileSystem, Path, ITerminal, FolderItem, InternalError } from '@rushstack/node-core-library';
+import { FileSystem, Path, ITerminal, FolderItem, InternalError, Async } from '@rushstack/node-core-library';
 
 import { RushConfigurationProject } from '../../api/RushConfigurationProject';
 import { ProjectChangeAnalyzer } from '../ProjectChangeAnalyzer';
@@ -19,6 +19,7 @@ export interface IProjectBuildCacheOptions {
   buildCacheConfiguration: BuildCacheConfiguration;
   projectConfiguration: RushProjectConfiguration;
   projectOutputFolderNames: ReadonlyArray<string>;
+  additionalProjectOutputFilePaths?: ReadonlyArray<string>;
   command: string;
   trackedProjectFiles: string[] | undefined;
   projectChangeAnalyzer: ProjectChangeAnalyzer;
@@ -44,16 +45,23 @@ export class ProjectBuildCache {
   private readonly _buildCacheEnabled: boolean;
   private readonly _cacheWriteEnabled: boolean;
   private readonly _projectOutputFolderNames: ReadonlyArray<string>;
+  private readonly _additionalProjectOutputFilePaths: ReadonlyArray<string>;
   private _cacheId: string | undefined;
 
   private constructor(cacheId: string | undefined, options: IProjectBuildCacheOptions) {
-    const { buildCacheConfiguration, projectConfiguration, projectOutputFolderNames } = options;
+    const {
+      buildCacheConfiguration,
+      projectConfiguration,
+      projectOutputFolderNames,
+      additionalProjectOutputFilePaths
+    } = options;
     this._project = projectConfiguration.project;
     this._localBuildCacheProvider = buildCacheConfiguration.localCacheProvider;
     this._cloudBuildCacheProvider = buildCacheConfiguration.cloudCacheProvider;
     this._buildCacheEnabled = buildCacheConfiguration.buildCacheEnabled;
     this._cacheWriteEnabled = buildCacheConfiguration.cacheWriteEnabled;
     this._projectOutputFolderNames = projectOutputFolderNames || [];
+    this._additionalProjectOutputFilePaths = additionalProjectOutputFilePaths || [];
     this._cacheId = cacheId;
   }
 
@@ -116,7 +124,7 @@ export class ProjectBuildCache {
     if (inputOutputFiles.length > 0) {
       terminal.writeWarningLine(
         'Unable to use build cache. The following files are used to calculate project state ' +
-          `and are considered project output: ${inputOutputFiles.join(', ')}`
+        `and are considered project output: ${inputOutputFiles.join(', ')}`
       );
       return false;
     } else {
@@ -251,14 +259,14 @@ export class ProjectBuildCache {
       } else {
         terminal.writeWarningLine(
           `"tar" exited with code ${tarExitCode} while attempting to create the cache entry. ` +
-            `See "${logFilePath}" for logs from the tar process.`
+          `See "${logFilePath}" for logs from the tar process.`
         );
         return false;
       }
     } else {
       terminal.writeWarningLine(
         `Unable to locate "tar". Please ensure that "tar" is on your PATH environment variable, or set the ` +
-          `${EnvironmentVariableNames.RUSH_TAR_BINARY_PATH} environment variable to the full path to the "tar" binary.`
+        `${EnvironmentVariableNames.RUSH_TAR_BINARY_PATH} environment variable to the full path to the "tar" binary.`
       );
       return false;
     }
@@ -359,6 +367,19 @@ export class ProjectBuildCache {
       return undefined;
     }
 
+    // Add additional output file paths
+    await Async.forEachAsync(
+      this._additionalProjectOutputFilePaths,
+      async (additionalProjectOutputFilePath) => {
+        const fullPath: string = `${projectFolderPath}/${additionalProjectOutputFilePath}`;
+        const pathExists: boolean = await FileSystem.existsAsync(fullPath);
+        if (pathExists) {
+          outputFilePaths.push(additionalProjectOutputFilePath);
+        }
+      },
+      { concurrency: 10 }
+    );
+
     // Ensure stable output path order.
     outputFilePaths.sort();
 

libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts

@@ -31,6 +31,10 @@ export interface IOperationExecutionResult {
    * Object used to report a summary at the end of the Rush invocation.
    */
   readonly stdioSummarizer: StdioSummarizer;
+  /**
+   * The value indicates the duration of the same operation without cache hit.
+   */
+  readonly nonCachedDurationMs: number | undefined;
 }
 
 /**

libraries/rush-lib/src/logic/operations/IOperationRunner.ts

@@ -5,6 +5,8 @@ import type { StdioSummarizer } from '@rushstack/terminal';
 import type { CollatedWriter } from '@rushstack/stream-collator';
 
 import type { OperationStatus } from './OperationStatus';
+import type { OperationStateFile } from './OperationStateFile';
+import type { IStopwatchResult } from '../../utilities/Stopwatch';
 
 /**
  * Information passed to the executing `IOperationRunner`
@@ -28,6 +30,16 @@ export interface IOperationRunnerContext {
    * Object used to report a summary at the end of the Rush invocation.
    */
   stdioSummarizer: StdioSummarizer;
+  /**
+   * Object used to record state of the operation.
+   *
+   * @internal
+   */
+  _operationStateFile?: OperationStateFile;
+  /**
+   * Object used to track elapsed time.
+   */
+  stopwatch: IStopwatchResult;
 }
 
 /**

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts

@@ -9,6 +9,7 @@ import { OperationStatus } from './OperationStatus';
 import { IOperationRunner, IOperationRunnerContext } from './IOperationRunner';
 import { Operation } from './Operation';
 import { Stopwatch } from '../../utilities/Stopwatch';
+import { OperationStateFile } from './OperationStateFile';
 
 export interface IOperationExecutionRecordContext {
   streamCollator: StreamCollator;
@@ -80,6 +81,7 @@ export class OperationExecutionRecord implements IOperationRunnerContext {
 
   public readonly runner: IOperationRunner;
   public readonly weight: number;
+  public readonly _operationStateFile: OperationStateFile | undefined;
 
   private readonly _context: IOperationExecutionRecordContext;
 
@@ -96,6 +98,12 @@ export class OperationExecutionRecord implements IOperationRunnerContext {
 
     this.runner = runner;
     this.weight = operation.weight;
+    if (operation.associatedPhase && operation.associatedProject) {
+      this._operationStateFile = new OperationStateFile({
+        phase: operation.associatedPhase,
+        rushProject: operation.associatedProject
+      });
+    }
     this._context = context;
   }
 
@@ -119,6 +127,11 @@ export class OperationExecutionRecord implements IOperationRunnerContext {
     return this._collatedWriter;
   }
 
+  public get nonCachedDurationMs(): number | undefined {
+    // Lazy calculated because the state file is created/restored later on
+    return this._operationStateFile?.state?.nonCachedDurationMs;
+  }
+
   public async executeAsync(onResult: (record: OperationExecutionRecord) => void): Promise<void> {
     this.status = OperationStatus.Executing;
     this.stopwatch.start();

libraries/rush-lib/src/logic/operations/OperationStateFile.ts

@@ -0,0 +1,85 @@
+// Copyright (c) Microsoft Corporation. All rights reserved. Licensed under the MIT license.
+// See LICENSE in the project root for license information.
+
+import { FileSystem, InternalError, JsonFile } from '@rushstack/node-core-library';
+import { RushConstants } from '../RushConstants';
+
+import type { IPhase } from '../../api/CommandLineConfiguration';
+import type { RushConfigurationProject } from '../../api/RushConfigurationProject';
+
+/**
+ * @internal
+ */
+export interface IOperationStateFileOptions {
+  rushProject: RushConfigurationProject;
+  phase: IPhase;
+}
+
+/**
+ * @internal
+ */
+export interface IOperationStateJson {
+  nonCachedDurationMs: number;
+}
+
+/**
+ * A helper class for managing the state file of a operation.
+ *
+ * @internal
+ */
+export class OperationStateFile {
+  private readonly _rushProject: RushConfigurationProject;
+  private readonly _filename: string;
+  private _state: IOperationStateJson | undefined;
+
+  public constructor(options: IOperationStateFileOptions) {
+    const { rushProject, phase } = options;
+    this._rushProject = rushProject;
+    this._filename = OperationStateFile._getFilename(phase, rushProject);
+  }
+
+  private static _getFilename(phase: IPhase, project: RushConfigurationProject): string {
+    const relativeFilename: string = OperationStateFile.getFilenameRelativeToProjectRoot(phase);
+    return `${project.projectFolder}/${relativeFilename}`;
+  }
+
+  /**
+   * ProjectBuildCache expects the relative path for better logging
+   *
+   * @internal
+   */
+  public static getFilenameRelativeToProjectRoot(phase: IPhase): string {
+    const identifier: string = phase.logFilenameIdentifier;
+    return `${RushConstants.projectRushFolderName}/${RushConstants.rushTempFolderName}/operation/${identifier}/state.json`;
+  }
+
+  /**
+   * Returns the filename of the metadata file.
+   */
+  public get filename(): string {
+    return this._filename;
+  }
+
+  public get state(): IOperationStateJson | undefined {
+    return this._state;
+  }
+
+  public async writeAsync(json: IOperationStateJson): Promise<void> {
+    await JsonFile.saveAsync(json, this._filename, { ensureFolderExists: true, updateExistingFile: true });
+    this._state = json;
+  }
+
+  public async tryRestoreAsync(): Promise<IOperationStateJson | undefined> {
+    try {
+      this._state = await JsonFile.loadAsync(this._filename);
+    } catch (error) {
+      if (FileSystem.isNotExistError(error as Error)) {
+        this._state = undefined;
+      } else {
+        // This should not happen
+        throw new InternalError(error);
+      }
+    }
+    return this._state;
+  }
+}