fix(timeline,cobuilds): cobuilt operations should reflect the cobuild time and not cache restore time

build-tests/rush-redis-cobuild-plugin-integration-test/sandbox/sharded-repo/projects/e/config/rush-project.json

@@ -4,16 +4,13 @@
     {
       "operationName": "_phase:build",
       "outputFolderNames": ["dist"],
-      "allowCobuildOrchestration": true,
-      "disableBuildCacheForOperation": true,
       "sharding": {
         "count": 75
       }
     },
     {
       "operationName": "_phase:build:shard",
-      "weight": 10,
-      "allowCobuildOrchestration": true
+      "weight": 10
     }
   ]
 }

common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json

@@ -0,0 +1,10 @@
+{
+  "changes": [
+    {
+      "packageName": "@microsoft/rush",
+      "comment": "Operations that were cobuilt now have the cobuild time correctly reflected across all agents.",
+      "type": "none"
+    }
+  ],
+  "packageName": "@microsoft/rush"
+}

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

@@ -584,7 +584,6 @@ export interface _INpmOptionsJson extends IPackageManagerOptionsJsonBase {
 
 // @alpha
 export interface IOperationExecutionResult {
-    readonly cobuildRunnerId: string | undefined;
     readonly error: Error | undefined;
     getStateHash(): string;
     getStateHashComponents(): ReadonlyArray<string>;
@@ -958,11 +957,17 @@ export class _OperationMetadataManager {
     // (undocumented)
     readonly stateFile: _OperationStateFile;
     // (undocumented)
-    tryRestoreAsync({ terminal, terminalProvider, errorLogPath }: {
+    tryRestoreAsync({ terminal, terminalProvider, errorLogPath, cobuildContextId, cobuildRunnerId }: {
         terminalProvider: ITerminalProvider;
         terminal: ITerminal;
         errorLogPath: string;
+        cobuildContextId?: string;
+        cobuildRunnerId?: string;
     }): Promise<void>;
+    // (undocumented)
+    tryRestoreStopwatch(originalStopwatch: IStopwatchResult): IStopwatchResult;
+    // (undocumented)
+    wasCobuilt: boolean;
 }
 
 // @internal

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

@@ -676,7 +676,9 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
         `  Press <${quitKey}> to gracefully exit.`,
         `  Press <${toggleWatcherKey}> to ${isPaused ? 'resume' : 'pause'}.`,
         `  Press <${invalidateKey}> to invalidate all projects.`,
-        `  Press <${changedProjectsOnlyKey}> to ${this._changedProjectsOnly ? 'disable' : 'enable'} changed-projects-only mode (${this._changedProjectsOnly ? 'ENABLED' : 'DISABLED'}).`
+        `  Press <${changedProjectsOnlyKey}> to ${
+          this._changedProjectsOnly ? 'disable' : 'enable'
+        } changed-projects-only mode (${this._changedProjectsOnly ? 'ENABLED' : 'DISABLED'}).`
       ];
       if (isPaused) {
         promptLines.push(`  Press <${buildOnceKey}> to build once.`);
@@ -820,8 +822,9 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
     // eslint-disable-next-line no-constant-condition
     while (!abortSignal.aborted) {
       // On the initial invocation, this promise will return immediately with the full set of projects
-      const { changedProjects, inputsSnapshot: state } =
-        await projectWatcher.waitForChangeAsync(onWaitingForChanges);
+      const { changedProjects, inputsSnapshot: state } = await projectWatcher.waitForChangeAsync(
+        onWaitingForChanges
+      );
 
       if (abortSignal.aborted) {
         return;
@@ -897,7 +900,7 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
       executionManagerOptions
     );
 
-    const { isInitial, isWatch, cobuildConfiguration } = options.executeOperationsContext;
+    const { isInitial, isWatch } = options.executeOperationsContext;
 
     let success: boolean = false;
     let result: IExecutionResult | undefined;
@@ -997,14 +1000,15 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
             continue;
           }
 
+          const { _operationMetadataManager: operationMetadataManager } =
+            operationResult as OperationExecutionRecord;
+
           const { startTime, endTime } = operationResult.stopwatch;
           jsonOperationResults[operation.name!] = {
             startTimestampMs: startTime,
             endTimestampMs: endTime,
             nonCachedDurationMs: operationResult.nonCachedDurationMs,
-            wasExecutedOnThisMachine:
-              !operationResult.cobuildRunnerId ||
-              operationResult.cobuildRunnerId === cobuildConfiguration?.cobuildRunnerId,
+            wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt !== true,
             result: operationResult.status,
             dependencies: Array.from(getNonSilentDependencies(operation)).sort()
           };

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

@@ -324,7 +324,9 @@ export class CacheableOperationPlugin implements IPhasedCommandPlugin {
                   await operationMetadataManager?.tryRestoreAsync({
                     terminalProvider,
                     terminal: buildCacheTerminal,
-                    errorLogPath
+                    errorLogPath,
+                    cobuildContextId: cobuildConfiguration?.cobuildContextId,
+                    cobuildRunnerId: cobuildConfiguration?.cobuildRunnerId
                   });
                 },
                 { createLogFile: false }

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

@@ -13,6 +13,7 @@ import type {
 import type { IExecutionResult } from './IOperationExecutionResult';
 import { OperationStatus } from './OperationStatus';
 import type { CobuildConfiguration } from '../../api/CobuildConfiguration';
+import type { OperationExecutionRecord } from './OperationExecutionRecord';
 
 const PLUGIN_NAME: 'ConsoleTimelinePlugin' = 'ConsoleTimelinePlugin';
 
@@ -127,20 +128,25 @@ interface ITimelineRecord {
 export interface IPrintTimelineParameters {
   terminal: ITerminal;
   result: IExecutionResult;
-  cobuildConfiguration: CobuildConfiguration | undefined;
+  cobuildConfiguration?: CobuildConfiguration;
+}
+
+interface ICachedDuration {
+  cached?: number;
+  uncached: number;
 }
 
 /**
  * Print a more detailed timeline and analysis of CPU usage for the build.
  * @internal
  */
-export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrintTimelineParameters): void {
+export function _printTimeline({ terminal, result }: IPrintTimelineParameters): void {
   //
   // Gather the operation records we'll be displaying. Do some inline max()
   // finding to reduce the number of times we need to loop through operations.
   //
 
-  const durationByPhase: Map<IPhase, number> = new Map();
+  const durationByPhase: Map<IPhase, ICachedDuration> = new Map();
 
   const data: ITimelineRecord[] = [];
   let longestNameLength: number = 0;
@@ -155,17 +161,33 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin
     }
 
     const { stopwatch } = operationResult;
+    const { _operationMetadataManager: operationMetadataManager } =
+      operationResult as OperationExecutionRecord;
+
+    let { startTime } = stopwatch;
+    const { endTime } = stopwatch;
 
-    const { startTime, endTime } = stopwatch;
+    const duration: ICachedDuration = { cached: undefined, uncached: stopwatch.duration };
 
     if (startTime && endTime) {
       const nameLength: number = operation.name?.length || 0;
       if (nameLength > longestNameLength) {
         longestNameLength = nameLength;
       }
+      const wasCobuilt: boolean = !!operationMetadataManager?.wasCobuilt;
+      if (
+        wasCobuilt &&
+        operationResult.status !== OperationStatus.FromCache &&
+        operationResult.nonCachedDurationMs
+      ) {
+        duration.cached = stopwatch.duration;
+        startTime = Math.max(0, endTime - operationResult.nonCachedDurationMs);
+        duration.uncached = (endTime - startTime) / 1000;
+      }
+
+      workDuration += stopwatch.duration;
 
-      const { duration } = stopwatch;
-      const durationString: string = duration.toFixed(1);
+      const durationString: string = duration.uncached.toFixed(1);
       const durationLength: number = durationString.length;
       if (durationLength > longestDurationLength) {
         longestDurationLength = durationLength;
@@ -177,21 +199,31 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin
       if (startTime < allStart) {
         allStart = startTime;
       }
-      workDuration += duration;
 
       const { associatedPhase } = operation;
 
-      durationByPhase.set(associatedPhase, (durationByPhase.get(associatedPhase) || 0) + duration);
+      if (associatedPhase) {
+        let durationRecord: ICachedDuration | undefined = durationByPhase.get(associatedPhase);
+        if (!durationRecord) {
+          durationRecord = {
+            cached: undefined,
+            uncached: 0
+          };
+          durationByPhase.set(associatedPhase, durationRecord);
+        }
+        if (duration.cached !== undefined) {
+          durationRecord.cached = (durationRecord.cached ?? 0) + duration.cached;
+        }
+        durationRecord.uncached += duration.uncached;
+      }
 
       data.push({
         startTime,
         endTime,
         durationString,
         name: operation.name,
         status: operationResult.status,
-        isExecuteByOtherCobuildRunner:
-          !!operationResult.cobuildRunnerId &&
-          operationResult.cobuildRunnerId !== cobuildConfiguration?.cobuildRunnerId
+        isExecuteByOtherCobuildRunner: wasCobuilt
       });
     }
   }
@@ -310,7 +342,11 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin
     }
 
     for (const [phase, duration] of durationByPhase.entries()) {
-      terminal.writeLine(`  ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${duration.toFixed(1)}s`);
+      const cachedDurationString: string = duration.cached
+        ? `, from cache: ${duration.cached.toFixed(1)}s`
+        : '';
+      const durationString: string = `${duration.uncached.toFixed(1)}s${cachedDurationString}`;
+      terminal.writeLine(`  ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${durationString}`);
     }
   }
 

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

@@ -44,10 +44,6 @@ export interface IOperationExecutionResult {
    * The value indicates the duration of the same operation without cache hit.
    */
   readonly nonCachedDurationMs: number | undefined;
-  /**
-   * The id of the runner which actually runs the building process in cobuild mode.
-   */
-  readonly cobuildRunnerId: string | undefined;
   /**
    * The relative path to the folder that contains operation metadata. This folder will be automatically included in cache entries.
    */

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

@@ -19,6 +19,7 @@ import { type IOperationExecutionRecordContext, OperationExecutionRecord } from
 import type { IExecutionResult } from './IOperationExecutionResult';
 import type { IEnvironment } from '../../utilities/Utilities';
 import type { IInputsSnapshot } from '../incremental/InputsSnapshot';
+import type { IStopwatchResult } from '../../utilities/Stopwatch';
 
 export interface IOperationExecutionManagerOptions {
   quietMode: boolean;
@@ -295,8 +296,8 @@ export class OperationExecutionManager {
     const status: OperationStatus = this._hasAnyFailures
       ? OperationStatus.Failure
       : this._hasAnyNonAllowedWarnings
-        ? OperationStatus.SuccessWithWarning
-        : OperationStatus.Success;
+      ? OperationStatus.SuccessWithWarning
+      : OperationStatus.Success;
 
     return {
       operationResults: this._executionRecords,
@@ -331,7 +332,9 @@ export class OperationExecutionManager {
    * Handles the result of the operation and propagates any relevant effects.
    */
   private _onOperationComplete(record: OperationExecutionRecord): void {
-    const { runner, name, status, silent } = record;
+    const { runner, name, status, silent, _operationMetadataManager: operationMetadataManager } = record;
+    const stopwatch: IStopwatchResult =
+      operationMetadataManager?.tryRestoreStopwatch(record.stopwatch) || record.stopwatch;
 
     switch (status) {
       /**
@@ -413,7 +416,7 @@ export class OperationExecutionManager {
       case OperationStatus.Success: {
         if (!silent) {
           record.collatedWriter.terminal.writeStdoutLine(
-            Colorize.green(`"${name}" completed successfully in ${record.stopwatch.toString()}.`)
+            Colorize.green(`"${name}" completed successfully in ${stopwatch.toString()}.`)
           );
         }
         break;
@@ -422,7 +425,7 @@ export class OperationExecutionManager {
       case OperationStatus.SuccessWithWarning: {
         if (!silent) {
           record.collatedWriter.terminal.writeStderrLine(
-            Colorize.yellow(`"${name}" completed with warnings in ${record.stopwatch.toString()}.`)
+            Colorize.yellow(`"${name}" completed with warnings in ${stopwatch.toString()}.`)
           );
         }
         this._hasAnyNonAllowedWarnings = this._hasAnyNonAllowedWarnings || !runner.warningsAreAllowed;

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

@@ -24,15 +24,15 @@ import { OperationMetadataManager } from './OperationMetadataManager';
 import type { IPhase } from '../../api/CommandLineConfiguration';
 import type { RushConfigurationProject } from '../../api/RushConfigurationProject';
 import { CollatedTerminalProvider } from '../../utilities/CollatedTerminalProvider';
+import type { IOperationExecutionResult } from './IOperationExecutionResult';
+import type { IInputsSnapshot } from '../incremental/InputsSnapshot';
+import { RushConstants } from '../RushConstants';
+import type { IEnvironment } from '../../utilities/Utilities';
 import {
   getProjectLogFilePaths,
   type ILogFilePaths,
   initializeProjectLogFilesAsync
 } from './ProjectLogWritable';
-import type { IOperationExecutionResult } from './IOperationExecutionResult';
-import type { IInputsSnapshot } from '../incremental/InputsSnapshot';
-import { RushConstants } from '../RushConstants';
-import type { IEnvironment } from '../../utilities/Utilities';
 
 export interface IOperationExecutionRecordContext {
   streamCollator: StreamCollator;
@@ -381,21 +381,24 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera
         this.status = this.operation.enabled
           ? await this.runner.executeAsync(this)
           : this.runner.isNoOp
-            ? OperationStatus.NoOp
-            : OperationStatus.Skipped;
+          ? OperationStatus.NoOp
+          : OperationStatus.Skipped;
       }
+      // Make sure that the stopwatch is stopped before reporting the result, otherwise endTime is undefined.
+      this.stopwatch.stop();
       // Delegate global state reporting
       await onResult(this);
     } catch (error) {
       this.status = OperationStatus.Failure;
       this.error = error;
+      // Make sure that the stopwatch is stopped before reporting the result, otherwise endTime is undefined.
+      this.stopwatch.stop();
       // Delegate global state reporting
       await onResult(this);
     } finally {
       if (this.isTerminal) {
         this._collatedWriter?.close();
         this.stdioSummarizer.close();
-        this.stopwatch.stop();
       }
     }
   }