From 99024b4e6d77746be0b4b5e62c6da82222b42b40 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Mon, 6 May 2024 18:46:55 -0400 Subject: [PATCH 01/29] fix: show cobuild timings for all agents --- common/reviews/api/rush-lib.api.md | 1 + .../cli/scriptActions/PhasedScriptAction.ts | 9 +++-- .../logic/operations/ConsoleTimelinePlugin.ts | 36 ++++++++++--------- .../operations/IOperationExecutionResult.ts | 4 +++ .../operations/OperationExecutionManager.ts | 9 +++-- .../operations/OperationExecutionRecord.ts | 26 ++++++++++---- .../test/OperationExecutionManager.test.ts | 2 +- libraries/rush-lib/src/utilities/Stopwatch.ts | 8 +++++ 8 files changed, 65 insertions(+), 30 deletions(-) diff --git a/common/reviews/api/rush-lib.api.md b/common/reviews/api/rush-lib.api.md index e423b7768e8..f7b1bdf078f 100644 --- a/common/reviews/api/rush-lib.api.md +++ b/common/reviews/api/rush-lib.api.md @@ -590,6 +590,7 @@ export interface IOperationExecutionResult { getStateHashComponents(): ReadonlyArray; readonly logFilePaths: ILogFilePaths | undefined; readonly metadataFolderPath: string | undefined; + readonly executedOnThisAgent: boolean; readonly nonCachedDurationMs: number | undefined; readonly operation: Operation; readonly silent: boolean; diff --git a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts index 4f02d4f08c3..f8b848523fa 100644 --- a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts +++ b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts @@ -676,7 +676,9 @@ export class PhasedScriptAction extends BaseScriptAction { ` 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 { // 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; diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index 85f540614ec..c176c273ecb 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -12,7 +12,6 @@ import type { } from '../../pluginFramework/PhasedCommandHooks'; import type { IExecutionResult } from './IOperationExecutionResult'; import { OperationStatus } from './OperationStatus'; -import type { CobuildConfiguration } from '../../api/CobuildConfiguration'; const PLUGIN_NAME: 'ConsoleTimelinePlugin' = 'ConsoleTimelinePlugin'; @@ -53,13 +52,12 @@ export class ConsoleTimelinePlugin implements IPhasedCommandPlugin { } public apply(hooks: PhasedCommandHooks): void { - hooks.afterExecuteOperations.tap( + hooks.afterExecuteOperations.tapPromise( PLUGIN_NAME, - (result: IExecutionResult, context: ICreateOperationsContext): void => { - _printTimeline({ + async (result: IExecutionResult, context: ICreateOperationsContext): Promise => { + await _printTimeline({ terminal: this._terminal, - result, - cobuildConfiguration: context.cobuildConfiguration + result }); } ); @@ -118,7 +116,7 @@ interface ITimelineRecord { durationString: string; name: string; status: OperationStatus; - isExecuteByOtherCobuildRunner: boolean; + isExecutedByOtherCobuildRunner: boolean; } /** @@ -127,14 +125,13 @@ interface ITimelineRecord { export interface IPrintTimelineParameters { terminal: ITerminal; result: IExecutionResult; - cobuildConfiguration: CobuildConfiguration | undefined; } /** * Print a more detailed timeline and analysis of CPU usage for the build. * @internal */ -export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrintTimelineParameters): void { +export async function _printTimeline({ terminal, result }: IPrintTimelineParameters): Promise { // // 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. @@ -154,17 +151,26 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin continue; } + const isExecutedByOtherCobuildRunner: boolean = + !!operationResult.cobuildRunnerId && !operationResult.executedOnThisAgent; + const { stopwatch } = operationResult; - const { startTime, endTime } = stopwatch; + const { startTime } = stopwatch; + let { endTime, duration } = stopwatch; if (startTime && endTime) { + // If this operation is cobuilt, print the cobuild time instead of the cache restore time. + if (isExecutedByOtherCobuildRunner) { + endTime = startTime + (operationResult.nonCachedDurationMs ?? 0); + duration = (endTime - startTime) / 1000.0; + } + const nameLength: number = operation.name?.length || 0; if (nameLength > longestNameLength) { longestNameLength = nameLength; } - const { duration } = stopwatch; const durationString: string = duration.toFixed(1); const durationLength: number = durationString.length; if (durationLength > longestDurationLength) { @@ -189,9 +195,7 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin durationString, name: operation.name, status: operationResult.status, - isExecuteByOtherCobuildRunner: - !!operationResult.cobuildRunnerId && - operationResult.cobuildRunnerId !== cobuildConfiguration?.cobuildRunnerId + isExecutedByOtherCobuildRunner }); } } @@ -234,8 +238,8 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin let hasCobuildSymbol: boolean = false; function getChartSymbol(record: ITimelineRecord): string { - const { isExecuteByOtherCobuildRunner, status } = record; - if (isExecuteByOtherCobuildRunner && COBUILD_REPORTABLE_STATUSES.has(status)) { + const { isExecutedByOtherCobuildRunner, status } = record; + if (isExecutedByOtherCobuildRunner && COBUILD_REPORTABLE_STATUSES.has(status)) { hasCobuildSymbol = true; return 'C'; } diff --git a/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts b/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts index 97fd565404b..490a605741e 100644 --- a/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts +++ b/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts @@ -56,6 +56,10 @@ export interface IOperationExecutionResult { * The paths to the log files, if applicable. */ readonly logFilePaths: ILogFilePaths | undefined; + /** + * Returns true if this operation was co-built using this machine, false if cobuilds are disabled or it was executed on another agent. + */ + readonly executedOnThisAgent: boolean; /** * Gets the hash of the state of all registered inputs to this operation. diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index 7908bb3fc40..a8460d9be46 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts @@ -26,6 +26,7 @@ export interface IOperationExecutionManagerOptions { parallelism: number; inputsSnapshot?: IInputsSnapshot; destination?: TerminalWritable; + cobuildConfiguration?: CobuildConfiguration; beforeExecuteOperationAsync?: (operation: OperationExecutionRecord) => Promise; afterExecuteOperationAsync?: (operation: OperationExecutionRecord) => Promise; @@ -109,6 +110,7 @@ export class OperationExecutionManager { this._hasAnyFailures = false; this._hasAnyNonAllowedWarnings = false; this._parallelism = parallelism; + this._cobuildConfiguration = cobuildConfiguration; this._beforeExecuteOperation = beforeExecuteOperation; this._afterExecuteOperation = afterExecuteOperation; @@ -144,7 +146,8 @@ export class OperationExecutionManager { createEnvironment: this._createEnvironmentForOperation, inputsSnapshot, debugMode, - quietMode + quietMode, + cobuildConfiguration: this._cobuildConfiguration }; // Sort the operations by name to ensure consistency and readability. @@ -295,8 +298,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, diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index 59fff7b38ed..becf1d2159e 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -24,11 +24,6 @@ import { OperationMetadataManager } from './OperationMetadataManager'; import type { IPhase } from '../../api/CommandLineConfiguration'; import type { RushConfigurationProject } from '../../api/RushConfigurationProject'; import { CollatedTerminalProvider } from '../../utilities/CollatedTerminalProvider'; -import { - getProjectLogFilePaths, - type ILogFilePaths, - initializeProjectLogFilesAsync -} from './ProjectLogWritable'; import type { IOperationExecutionResult } from './IOperationExecutionResult'; import type { IInputsSnapshot } from '../incremental/InputsSnapshot'; import { RushConstants } from '../RushConstants'; @@ -40,6 +35,7 @@ export interface IOperationExecutionRecordContext { createEnvironment?: (record: OperationExecutionRecord) => IEnvironment; inputsSnapshot: IInputsSnapshot | undefined; + cobuildConfiguration?: CobuildConfiguration; debugMode: boolean; quietMode: boolean; } @@ -194,6 +190,13 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera return TERMINAL_STATUSES.has(this.status); } + public get executedOnThisAgent(): boolean { + return ( + !!this._context.cobuildConfiguration && + this._context.cobuildConfiguration?.cobuildRunnerId !== this.cobuildRunnerId + ); + } + /** * The current execution status of an operation. Operations start in the 'ready' state, * but can be 'blocked' if an upstream operation failed. It is 'executing' when @@ -381,8 +384,8 @@ 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; } // Delegate global state reporting await onResult(this); @@ -396,6 +399,15 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera this._collatedWriter?.close(); this.stdioSummarizer.close(); this.stopwatch.stop(); + if (!this.executedOnThisAgent && this.nonCachedDurationMs) { + const { startTime } = this.stopwatch; + if (startTime) { + this.stopwatch = Stopwatch.fromState({ + startTime, + endTime: startTime + this.nonCachedDurationMs + }); + } + } } } } diff --git a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts index 2520738854d..f6366597fbb 100644 --- a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts +++ b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts @@ -285,7 +285,7 @@ describe(OperationExecutionManager.name, () => { ); const result: IExecutionResult = await executionManager.executeAsync(); - _printTimeline({ terminal: mockTerminal, result, cobuildConfiguration: undefined }); + await _printTimeline({ terminal: mockTerminal, result }); _printOperationStatus(mockTerminal, result); const allMessages: string = mockWritable.getAllOutput(); expect(allMessages).toContain('Build step 1'); diff --git a/libraries/rush-lib/src/utilities/Stopwatch.ts b/libraries/rush-lib/src/utilities/Stopwatch.ts index 8495915a0e1..b4e55df8e44 100644 --- a/libraries/rush-lib/src/utilities/Stopwatch.ts +++ b/libraries/rush-lib/src/utilities/Stopwatch.ts @@ -52,6 +52,14 @@ export class Stopwatch implements IStopwatchResult { this._state = StopwatchState.Stopped; } + public static fromState({ startTime, endTime }: { startTime: number; endTime: number }): Stopwatch { + const stopwatch: Stopwatch = new Stopwatch(); + stopwatch._startTime = startTime; + stopwatch._endTime = endTime; + stopwatch._state = StopwatchState.Stopped; + return stopwatch; + } + /** * Static helper function which creates a stopwatch which is immediately started */ From 090ce43800a20f41f77d0285c56b9a4521a81e41 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Mon, 6 May 2024 20:00:40 -0400 Subject: [PATCH 02/29] stopwatch timing isn't correct --- .../src/logic/operations/ConsoleTimelinePlugin.ts | 6 ------ .../src/logic/operations/OperationExecutionRecord.ts | 9 +++++---- 2 files changed, 5 insertions(+), 10 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index c176c273ecb..7d80bb6d919 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -160,12 +160,6 @@ export async function _printTimeline({ terminal, result }: IPrintTimelineParamet let { endTime, duration } = stopwatch; if (startTime && endTime) { - // If this operation is cobuilt, print the cobuild time instead of the cache restore time. - if (isExecutedByOtherCobuildRunner) { - endTime = startTime + (operationResult.nonCachedDurationMs ?? 0); - duration = (endTime - startTime) / 1000.0; - } - const nameLength: number = operation.name?.length || 0; if (nameLength > longestNameLength) { longestNameLength = nameLength; diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index becf1d2159e..383670b2b83 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -387,18 +387,15 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera ? OperationStatus.NoOp : OperationStatus.Skipped; } - // Delegate global state reporting - await onResult(this); } catch (error) { this.status = OperationStatus.Failure; this.error = error; - // Delegate global state reporting - await onResult(this); } finally { if (this.isTerminal) { this._collatedWriter?.close(); this.stdioSummarizer.close(); this.stopwatch.stop(); + console.warn('stopping', this.executedOnThisAgent, this.nonCachedDurationMs, this.stopwatch.duration); if (!this.executedOnThisAgent && this.nonCachedDurationMs) { const { startTime } = this.stopwatch; if (startTime) { @@ -408,6 +405,10 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera }); } } + // Delegate global state reporting + await onResult(this); + this._collatedWriter?.close(); + this.stdioSummarizer.close(); } } } From 6adcbdf35f2bfdef916866f8b4aa4b085f533a5b Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 7 May 2024 12:06:12 -0400 Subject: [PATCH 03/29] cleanup --- .../rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts | 3 +-- .../rush-lib/src/logic/operations/OperationExecutionRecord.ts | 1 - 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index 7d80bb6d919..99a44660698 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -156,8 +156,7 @@ export async function _printTimeline({ terminal, result }: IPrintTimelineParamet const { stopwatch } = operationResult; - const { startTime } = stopwatch; - let { endTime, duration } = stopwatch; + const { startTime, endTime, duration } = stopwatch; if (startTime && endTime) { const nameLength: number = operation.name?.length || 0; diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index 383670b2b83..22d77bb64eb 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -395,7 +395,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera this._collatedWriter?.close(); this.stdioSummarizer.close(); this.stopwatch.stop(); - console.warn('stopping', this.executedOnThisAgent, this.nonCachedDurationMs, this.stopwatch.duration); if (!this.executedOnThisAgent && this.nonCachedDurationMs) { const { startTime } = this.stopwatch; if (startTime) { From 872b12a6b2d93bbb0834ad2362f64a14fe214672 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 7 May 2024 12:22:50 -0400 Subject: [PATCH 04/29] fixing when cache is flushed to disk --- .../operations/OperationExecutionManager.ts | 5 +--- .../operations/OperationExecutionRecord.ts | 26 ++++++++++++++++--- 2 files changed, 23 insertions(+), 8 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index a8460d9be46..7a7f7ca1a62 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts @@ -260,9 +260,7 @@ export class OperationExecutionManager { await this._beforeExecuteOperations?.(this._executionRecords); - // This function is a callback because it may write to the collatedWriter before - // operation.executeAsync returns (and cleans up the writer) - const onOperationCompleteAsync: (record: OperationExecutionRecord) => Promise = async ( + const beforeOperationResult: (record: OperationExecutionRecord) => Promise = async ( record: OperationExecutionRecord ) => { try { @@ -272,7 +270,6 @@ export class OperationExecutionManager { record.error = e; record.status = OperationStatus.Failure; } - this._onOperationComplete(record); }; const onOperationStartAsync: ( diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index 22d77bb64eb..e414a53c4bb 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -191,9 +191,16 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera } public get executedOnThisAgent(): boolean { + console.log( + 'this._context.cobuildConfiguration', + this._context.cobuildConfiguration?.cobuildRunnerId, + this.cobuildRunnerId + ); return ( !!this._context.cobuildConfiguration && - this._context.cobuildConfiguration?.cobuildRunnerId !== this.cobuildRunnerId + // this can happen if this property is retrieved before `beforeResult` is called. + this.cobuildRunnerId !== undefined && + this._context.cobuildConfiguration?.cobuildRunnerId === this.cobuildRunnerId ); } @@ -362,9 +369,11 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera public async executeAsync({ onStart, - onResult + onResult, + beforeResult }: { onStart: (record: OperationExecutionRecord) => Promise; + beforeResult: (record: OperationExecutionRecord) => Promise; onResult: (record: OperationExecutionRecord) => Promise; }): Promise { if (!this.isTerminal) { @@ -391,10 +400,17 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera this.status = OperationStatus.Failure; this.error = error; } finally { + // We may need to clean up and finalize resources (_operationMetadataManager for example needs to be saved by CacheableOperationPlugin) + await beforeResult(this); if (this.isTerminal) { this._collatedWriter?.close(); this.stdioSummarizer.close(); this.stopwatch.stop(); + console.log( + `Operation ${this.operation.name} took ${this.stopwatch.duration}ms`, + this.nonCachedDurationMs, + this.executedOnThisAgent + ); if (!this.executedOnThisAgent && this.nonCachedDurationMs) { const { startTime } = this.stopwatch; if (startTime) { @@ -404,8 +420,10 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera }); } } - // Delegate global state reporting - await onResult(this); + } + // Delegate global state reporting + await onResult(this); + if (this.status !== OperationStatus.RemoteExecuting) { this._collatedWriter?.close(); this.stdioSummarizer.close(); } From 944d13a411eaf6dda1c6b28ff0c3446abce9bbeb Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 7 May 2024 12:36:40 -0400 Subject: [PATCH 05/29] add changeset --- .../sennyeya-operation-timings_2024-05-07-16-36.json | 10 ++++++++++ 1 file changed, 10 insertions(+) create mode 100644 common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json diff --git a/common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json b/common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json new file mode 100644 index 00000000000..48ae2c8d937 --- /dev/null +++ b/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 correct reflected across all agents.", + "type": "none" + } + ], + "packageName": "@microsoft/rush" +} \ No newline at end of file From 3ddde099b3d99b6cc866dc5dfc2bfd96469f75af Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 7 May 2024 12:54:22 -0400 Subject: [PATCH 06/29] fix snapshot --- .../OperationExecutionManager.test.ts.snap | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap b/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap index 7492df9711e..3446fd2adb0 100644 --- a/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap +++ b/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap @@ -241,7 +241,7 @@ Array [ }, Object { "kind": "O", - "text": "[gray]--[[default] [yellow]WARNING: success with warnings (failure)[default] [gray]]---------------[[default] [white]0.20 seconds[default] [gray]]--[default] + "text": "[gray]--[[default] [yellow]WARNING: success with warnings (failure)[default] [gray]]---------------[[default] [white]0.10 seconds[default] [gray]]--[default] ", }, @@ -329,7 +329,7 @@ Array [ }, Object { "kind": "O", - "text": "[gray]--[[default] [yellow]WARNING: success with warnings (success)[default] [gray]]---------------[[default] [white]0.20 seconds[default] [gray]]--[default] + "text": "[gray]--[[default] [yellow]WARNING: success with warnings (success)[default] [gray]]---------------[[default] [white]0.10 seconds[default] [gray]]--[default] ", }, @@ -408,7 +408,7 @@ Array [ }, Object { "kind": "O", - "text": "[cyan]success with warnings (success)[default] [gray][default][yellow]!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!![default][gray][default] [white]0.2s[default] + "text": "[cyan]success with warnings (success)[default] [gray][default][yellow]!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!![default][gray][default] [white]0.1s[default] ", }, Object { @@ -418,12 +418,12 @@ Array [ }, Object { "kind": "O", - "text": "LEGEND: Total Work: 0.2s + "text": "LEGEND: Total Work: 0.1s ", }, Object { "kind": "O", - "text": " [#] Success [!] Failed/warnings [%] Skipped/cached/no-op Wall Clock: 0.2s + "text": " [#] Success [!] Failed/warnings [%] Skipped/cached/no-op Wall Clock: 0.1s ", }, Object { @@ -466,7 +466,7 @@ Array [ }, Object { "kind": "O", - "text": "[gray]--[[default] [yellow]WARNING: success with warnings (success)[default] [gray]]---------------[[default] [white]0.20 seconds[default] [gray]]--[default] + "text": "[gray]--[[default] [yellow]WARNING: success with warnings (success)[default] [gray]]---------------[[default] [white]0.10 seconds[default] [gray]]--[default] ", }, From 523e08f291a50349b8ccad9df2acbd6e01f78add Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 7 May 2024 12:54:53 -0400 Subject: [PATCH 07/29] fix linting --- .../src/logic/operations/OperationExecutionManager.ts | 4 +++- .../src/logic/operations/OperationExecutionRecord.ts | 10 ---------- 2 files changed, 3 insertions(+), 11 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index 7a7f7ca1a62..85fd51ce1d5 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts @@ -283,7 +283,9 @@ export class OperationExecutionManager { async (record: OperationExecutionRecord) => { await record.executeAsync({ onStart: onOperationStartAsync, - onResult: onOperationCompleteAsync + beforeResult: beforeOperationResult, + onResult: async (finishedRecord: OperationExecutionRecord) => + this._onOperationComplete(finishedRecord) }); }, { diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index e414a53c4bb..abfb09bf70d 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -191,11 +191,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera } public get executedOnThisAgent(): boolean { - console.log( - 'this._context.cobuildConfiguration', - this._context.cobuildConfiguration?.cobuildRunnerId, - this.cobuildRunnerId - ); return ( !!this._context.cobuildConfiguration && // this can happen if this property is retrieved before `beforeResult` is called. @@ -406,11 +401,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera this._collatedWriter?.close(); this.stdioSummarizer.close(); this.stopwatch.stop(); - console.log( - `Operation ${this.operation.name} took ${this.stopwatch.duration}ms`, - this.nonCachedDurationMs, - this.executedOnThisAgent - ); if (!this.executedOnThisAgent && this.nonCachedDurationMs) { const { startTime } = this.stopwatch; if (startTime) { From dd67e3fd7bcea99f9d11a72c6426341f1c69755f Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 7 May 2024 13:06:20 -0400 Subject: [PATCH 08/29] adjust the check to check for cobuild disabled --- .../rush-lib/src/logic/operations/OperationExecutionRecord.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index abfb09bf70d..d3d3b86ad02 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -191,8 +191,10 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera } public get executedOnThisAgent(): boolean { + if (!this._context.cobuildConfiguration) { + return this.cobuildRunnerId === undefined; + } return ( - !!this._context.cobuildConfiguration && // this can happen if this property is retrieved before `beforeResult` is called. this.cobuildRunnerId !== undefined && this._context.cobuildConfiguration?.cobuildRunnerId === this.cobuildRunnerId From 48e236138b1ae9463d96d41cafbc283fe83d3c7f Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 10 May 2024 08:42:20 -0400 Subject: [PATCH 09/29] make it not async --- .../rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts | 4 ++-- .../logic/operations/test/OperationExecutionManager.test.ts | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index 99a44660698..5ede3a09ef5 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -55,7 +55,7 @@ export class ConsoleTimelinePlugin implements IPhasedCommandPlugin { hooks.afterExecuteOperations.tapPromise( PLUGIN_NAME, async (result: IExecutionResult, context: ICreateOperationsContext): Promise => { - await _printTimeline({ + _printTimeline({ terminal: this._terminal, result }); @@ -131,7 +131,7 @@ export interface IPrintTimelineParameters { * Print a more detailed timeline and analysis of CPU usage for the build. * @internal */ -export async function _printTimeline({ terminal, result }: IPrintTimelineParameters): Promise { +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. diff --git a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts index f6366597fbb..6260d2ae368 100644 --- a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts +++ b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts @@ -285,7 +285,7 @@ describe(OperationExecutionManager.name, () => { ); const result: IExecutionResult = await executionManager.executeAsync(); - await _printTimeline({ terminal: mockTerminal, result }); + _printTimeline({ terminal: mockTerminal, result }); _printOperationStatus(mockTerminal, result); const allMessages: string = mockWritable.getAllOutput(); expect(allMessages).toContain('Build step 1'); From bdeffcbb831f03e6e3de32b71efbad5796941e86 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 10 May 2024 08:54:29 -0400 Subject: [PATCH 10/29] make operation tracking async --- .../src/logic/operations/OperationExecutionManager.ts | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index 85fd51ce1d5..9e7931b766f 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts @@ -284,8 +284,7 @@ export class OperationExecutionManager { await record.executeAsync({ onStart: onOperationStartAsync, beforeResult: beforeOperationResult, - onResult: async (finishedRecord: OperationExecutionRecord) => - this._onOperationComplete(finishedRecord) + onResult: this._onOperationComplete }); }, { @@ -332,7 +331,7 @@ export class OperationExecutionManager { /** * Handles the result of the operation and propagates any relevant effects. */ - private _onOperationComplete(record: OperationExecutionRecord): void { + private async _onOperationComplete(record: OperationExecutionRecord): Promise { const { runner, name, status, silent } = record; switch (status) { From 77df07b0e2946f2a852ee348f6f2aac9b16d24f6 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 10 May 2024 09:04:53 -0400 Subject: [PATCH 11/29] fix binding --- .../rush-lib/src/logic/operations/OperationExecutionManager.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index 9e7931b766f..2ebc963705e 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts @@ -284,7 +284,7 @@ export class OperationExecutionManager { await record.executeAsync({ onStart: onOperationStartAsync, beforeResult: beforeOperationResult, - onResult: this._onOperationComplete + onResult: this._onOperationComplete.bind(this) }); }, { From cad6b5bcef0b0fdec2986c2c39f0f0be98775999 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 10 May 2024 09:56:45 -0400 Subject: [PATCH 12/29] small adjustments to make the operations look better in timeline view --- .../src/logic/operations/OperationExecutionRecord.ts | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index d3d3b86ad02..39b00eb71d9 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -376,7 +376,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera if (!this.isTerminal) { this.stopwatch.reset(); } - this.stopwatch.start(); this.status = OperationStatus.Executing; try { @@ -403,10 +402,15 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera this._collatedWriter?.close(); this.stdioSummarizer.close(); this.stopwatch.stop(); - if (!this.executedOnThisAgent && this.nonCachedDurationMs) { + if ( + !this.executedOnThisAgent && + this.nonCachedDurationMs && + this.status !== OperationStatus.FromCache + ) { const { startTime } = this.stopwatch; if (startTime) { this.stopwatch = Stopwatch.fromState({ + // use endtime as it's the more accurate version of when this operation was marked as complete. startTime, endTime: startTime + this.nonCachedDurationMs }); From 54d92655c2168d47a000a1113897e2aa02be0c75 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey <159921952+aramissennyeydd@users.noreply.github.com> Date: Tue, 14 May 2024 05:42:18 -0700 Subject: [PATCH 13/29] Apply suggestions from code review Co-authored-by: Ian Clanton-Thuon --- .../rush/sennyeya-operation-timings_2024-05-07-16-36.json | 2 +- .../rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json b/common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json index 48ae2c8d937..bb76fd9a8c1 100644 --- a/common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json +++ b/common/changes/@microsoft/rush/sennyeya-operation-timings_2024-05-07-16-36.json @@ -2,7 +2,7 @@ "changes": [ { "packageName": "@microsoft/rush", - "comment": "Operations that were cobuilt now have the cobuild time correct reflected across all agents.", + "comment": "Operations that were cobuilt now have the cobuild time correctly reflected across all agents.", "type": "none" } ], diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index 5ede3a09ef5..7894f9a80dd 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -52,9 +52,9 @@ export class ConsoleTimelinePlugin implements IPhasedCommandPlugin { } public apply(hooks: PhasedCommandHooks): void { - hooks.afterExecuteOperations.tapPromise( + hooks.afterExecuteOperations.tap( PLUGIN_NAME, - async (result: IExecutionResult, context: ICreateOperationsContext): Promise => { + (result: IExecutionResult, context: ICreateOperationsContext): void => { _printTimeline({ terminal: this._terminal, result From 19f98fdc97cdcf03ae7cbd4101210f71f7765484 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 14 May 2024 05:44:07 -0700 Subject: [PATCH 14/29] adjust comment --- .../rush-lib/src/logic/operations/IOperationExecutionResult.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts b/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts index 490a605741e..7df7332270f 100644 --- a/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts +++ b/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts @@ -57,7 +57,7 @@ export interface IOperationExecutionResult { */ readonly logFilePaths: ILogFilePaths | undefined; /** - * Returns true if this operation was co-built using this machine, false if cobuilds are disabled or it was executed on another agent. + * Returns true if this operation was co-built using this machine or cobuilds are disabled, false it was executed on another agent. */ readonly executedOnThisAgent: boolean; From 41e9cd5604a011b576de097977a3f8c4911e422d Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 21 May 2024 16:29:20 -0400 Subject: [PATCH 15/29] flip stopwatch usage --- .../src/logic/operations/OperationExecutionRecord.ts | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index 39b00eb71d9..f21fc662f29 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -99,7 +99,7 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera */ public readonly consumers: Set = new Set(); - public readonly stopwatch: Stopwatch = new Stopwatch(); + private _stopwatch: Stopwatch = new Stopwatch(); public readonly stdioSummarizer: StdioSummarizer = new StdioSummarizer({ // Allow writing to this object after transforms have been closed. We clean it up manually in a finally block. preventAutoclose: true @@ -160,6 +160,10 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera return this._context.quietMode; } + public get stopwatch(): Stopwatch { + return this._stopwatch; + } + public get collatedWriter(): CollatedWriter { // Lazy instantiate because the registerTask() call affects display ordering if (!this._collatedWriter) { @@ -409,7 +413,7 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera ) { const { startTime } = this.stopwatch; if (startTime) { - this.stopwatch = Stopwatch.fromState({ + this._stopwatch = Stopwatch.fromState({ // use endtime as it's the more accurate version of when this operation was marked as complete. startTime, endTime: startTime + this.nonCachedDurationMs From 088141d2b7c29544c08eaf765e866b03a8467f98 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Tue, 21 May 2024 16:54:44 -0400 Subject: [PATCH 16/29] add a comment --- .../rush-lib/src/logic/operations/OperationExecutionRecord.ts | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index f21fc662f29..ca4e68bdd2e 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -99,6 +99,10 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera */ public readonly consumers: Set = new Set(); + /** + * The stopwatch used to measure the duration of this operation. This is purposefully not + * readonly as we want to override it in the case of a cache hit. + */ private _stopwatch: Stopwatch = new Stopwatch(); public readonly stdioSummarizer: StdioSummarizer = new StdioSummarizer({ // Allow writing to this object after transforms have been closed. We clean it up manually in a finally block. From c1d2f2ddd16248e4f459d9be0e258877d49a8870 Mon Sep 17 00:00:00 2001 From: Ian Clanton-Thuon Date: Fri, 24 May 2024 19:42:01 -0700 Subject: [PATCH 17/29] Un-async _onOperationComplete. --- .../rush-lib/src/logic/operations/OperationExecutionRecord.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index ca4e68bdd2e..1155ce8afab 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -379,7 +379,7 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera }: { onStart: (record: OperationExecutionRecord) => Promise; beforeResult: (record: OperationExecutionRecord) => Promise; - onResult: (record: OperationExecutionRecord) => Promise; + onResult: (record: OperationExecutionRecord) => Promise | void; }): Promise { if (!this.isTerminal) { this.stopwatch.reset(); From e6f821efc9db60f1a266ff260728eac9af93267e Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Thu, 26 Dec 2024 10:22:50 -0700 Subject: [PATCH 18/29] un-async onOperationComplete Signed-off-by: Aramis Sennyey --- .../src/logic/operations/OperationExecutionManager.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index 2ebc963705e..08c13e097fd 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts @@ -296,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 +331,7 @@ export class OperationExecutionManager { /** * Handles the result of the operation and propagates any relevant effects. */ - private async _onOperationComplete(record: OperationExecutionRecord): Promise { + private _onOperationComplete(record: OperationExecutionRecord): void { const { runner, name, status, silent } = record; switch (status) { From 93e2aa837203e76b5d45e0a114aa8b5e29211890 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Thu, 26 Dec 2024 10:44:40 -0700 Subject: [PATCH 19/29] fix build Signed-off-by: Aramis Sennyey --- common/reviews/api/rush-lib.api.md | 2 +- .../src/logic/operations/OperationExecutionRecord.ts | 12 ++++++------ 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/common/reviews/api/rush-lib.api.md b/common/reviews/api/rush-lib.api.md index f7b1bdf078f..d3f065be525 100644 --- a/common/reviews/api/rush-lib.api.md +++ b/common/reviews/api/rush-lib.api.md @@ -586,11 +586,11 @@ export interface _INpmOptionsJson extends IPackageManagerOptionsJsonBase { export interface IOperationExecutionResult { readonly cobuildRunnerId: string | undefined; readonly error: Error | undefined; + readonly executedOnThisAgent: boolean; getStateHash(): string; getStateHashComponents(): ReadonlyArray; readonly logFilePaths: ILogFilePaths | undefined; readonly metadataFolderPath: string | undefined; - readonly executedOnThisAgent: boolean; readonly nonCachedDurationMs: number | undefined; readonly operation: Operation; readonly silent: boolean; diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index 1155ce8afab..f59b3b41843 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -28,6 +28,12 @@ import type { IOperationExecutionResult } from './IOperationExecutionResult'; import type { IInputsSnapshot } from '../incremental/InputsSnapshot'; import { RushConstants } from '../RushConstants'; import type { IEnvironment } from '../../utilities/Utilities'; +import type { CobuildConfiguration } from '../../api/CobuildConfiguration'; +import { + getProjectLogFilePaths, + type ILogFilePaths, + initializeProjectLogFilesAsync +} from './ProjectLogWritable'; export interface IOperationExecutionRecordContext { streamCollator: StreamCollator; @@ -425,12 +431,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera } } } - // Delegate global state reporting - await onResult(this); - if (this.status !== OperationStatus.RemoteExecuting) { - this._collatedWriter?.close(); - this.stdioSummarizer.close(); - } } } } From c4306ea96d68801129aaa4055a36d0edf45c7029 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Thu, 26 Dec 2024 11:15:15 -0700 Subject: [PATCH 20/29] rebase fixes Signed-off-by: Aramis Sennyey --- .../sharded-repo/projects/e/config/rush-project.json | 5 +---- .../src/logic/operations/OperationExecutionRecord.ts | 11 +++++++---- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/build-tests/rush-redis-cobuild-plugin-integration-test/sandbox/sharded-repo/projects/e/config/rush-project.json b/build-tests/rush-redis-cobuild-plugin-integration-test/sandbox/sharded-repo/projects/e/config/rush-project.json index e6534be5bc8..a5e85aedd69 100644 --- a/build-tests/rush-redis-cobuild-plugin-integration-test/sandbox/sharded-repo/projects/e/config/rush-project.json +++ b/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 } ] } diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index f59b3b41843..4566f6136cb 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -387,8 +387,8 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera beforeResult: (record: OperationExecutionRecord) => Promise; onResult: (record: OperationExecutionRecord) => Promise | void; }): Promise { - if (!this.isTerminal) { - this.stopwatch.reset(); + if (this.stopwatch.startTime === undefined) { + this.stopwatch.start(); } this.status = OperationStatus.Executing; @@ -413,8 +413,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera // We may need to clean up and finalize resources (_operationMetadataManager for example needs to be saved by CacheableOperationPlugin) await beforeResult(this); if (this.isTerminal) { - this._collatedWriter?.close(); - this.stdioSummarizer.close(); this.stopwatch.stop(); if ( !this.executedOnThisAgent && @@ -431,6 +429,11 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera } } } + await onResult(this); + if (this.isTerminal) { + this._collatedWriter?.close(); + this.stdioSummarizer.close(); + } } } } From f2c3c2603e11ba232da8d4f053d8181b0e2250cd Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Mon, 30 Dec 2024 15:15:21 -0700 Subject: [PATCH 21/29] address PR feedback, move cobuild state to operation metadata manager Signed-off-by: Aramis Sennyey --- common/reviews/api/rush-lib.api.md | 10 +- .../cli/scriptActions/PhasedScriptAction.ts | 13 +- .../operations/CacheableOperationPlugin.ts | 4 +- .../logic/operations/ConsoleTimelinePlugin.ts | 65 +++- .../operations/IOperationExecutionResult.ts | 8 - .../operations/OperationExecutionManager.ts | 26 +- .../operations/OperationExecutionRecord.ts | 60 +-- .../operations/OperationMetadataManager.ts | 25 +- .../OperationResultSummarizerPlugin.ts | 25 +- .../test/OperationExecutionManager.test.ts | 110 +++++- .../OperationExecutionManager.test.ts.snap | 352 ++++++++++++++++++ 11 files changed, 602 insertions(+), 96 deletions(-) diff --git a/common/reviews/api/rush-lib.api.md b/common/reviews/api/rush-lib.api.md index d3f065be525..bb74a60c40e 100644 --- a/common/reviews/api/rush-lib.api.md +++ b/common/reviews/api/rush-lib.api.md @@ -584,9 +584,7 @@ export interface _INpmOptionsJson extends IPackageManagerOptionsJsonBase { // @alpha export interface IOperationExecutionResult { - readonly cobuildRunnerId: string | undefined; readonly error: Error | undefined; - readonly executedOnThisAgent: boolean; getStateHash(): string; getStateHashComponents(): ReadonlyArray; readonly logFilePaths: ILogFilePaths | undefined; @@ -959,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; + // (undocumented) + tryRestoreStopwatch(originalStopwatch: IStopwatchResult): IStopwatchResult; + // (undocumented) + wasCobuilt: boolean; } // @internal diff --git a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts index f8b848523fa..c3a56d862c0 100644 --- a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts +++ b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts @@ -59,6 +59,7 @@ import { getVariantAsync, VARIANT_PARAMETER } from '../../api/Variants'; import { Selection } from '../../logic/Selection'; import { NodeDiagnosticDirPlugin } from '../../logic/operations/NodeDiagnosticDirPlugin'; import { DebugHashesPlugin } from '../../logic/operations/DebugHashesPlugin'; +import type { IOperationStateJson } from '../../logic/operations/OperationStateFile'; /** * Constructor parameters for PhasedScriptAction. @@ -1000,14 +1001,20 @@ export class PhasedScriptAction extends BaseScriptAction { continue; } + const { _operationMetadataManager: operationMetadataManager } = + operationResult as OperationExecutionRecord; + const metadataState: IOperationStateJson | undefined = operationMetadataManager?.stateFile.state; + const { startTime, endTime } = operationResult.stopwatch; + const wasExecutedOnThisMachine: boolean = cobuildConfiguration?.cobuildFeatureEnabled + ? metadataState?.cobuildContextId === cobuildConfiguration?.cobuildContextId && + metadataState?.cobuildRunnerId === cobuildConfiguration?.cobuildRunnerId + : true; jsonOperationResults[operation.name!] = { startTimestampMs: startTime, endTimestampMs: endTime, nonCachedDurationMs: operationResult.nonCachedDurationMs, - wasExecutedOnThisMachine: - !operationResult.cobuildRunnerId || - operationResult.cobuildRunnerId === cobuildConfiguration?.cobuildRunnerId, + wasExecutedOnThisMachine, result: operationResult.status, dependencies: Array.from(getNonSilentDependencies(operation)).sort() }; diff --git a/libraries/rush-lib/src/logic/operations/CacheableOperationPlugin.ts b/libraries/rush-lib/src/logic/operations/CacheableOperationPlugin.ts index 48217f4494e..3ccddb4bbeb 100644 --- a/libraries/rush-lib/src/logic/operations/CacheableOperationPlugin.ts +++ b/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 } diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index 7894f9a80dd..159ca52fb40 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -12,6 +12,8 @@ import type { } from '../../pluginFramework/PhasedCommandHooks'; 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'; @@ -57,7 +59,8 @@ export class ConsoleTimelinePlugin implements IPhasedCommandPlugin { (result: IExecutionResult, context: ICreateOperationsContext): void => { _printTimeline({ terminal: this._terminal, - result + result, + cobuildConfiguration: context.cobuildConfiguration }); } ); @@ -116,7 +119,7 @@ interface ITimelineRecord { durationString: string; name: string; status: OperationStatus; - isExecutedByOtherCobuildRunner: boolean; + isExecuteByOtherCobuildRunner: boolean; } /** @@ -125,6 +128,12 @@ interface ITimelineRecord { export interface IPrintTimelineParameters { terminal: ITerminal; result: IExecutionResult; + cobuildConfiguration?: CobuildConfiguration; +} + +interface ICachedDuration { + cached?: number; + uncached: number; } /** @@ -137,7 +146,7 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): // finding to reduce the number of times we need to loop through operations. // - const durationByPhase: Map = new Map(); + const durationByPhase: Map = new Map(); const data: ITimelineRecord[] = []; let longestNameLength: number = 0; @@ -151,20 +160,35 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): continue; } - const isExecutedByOtherCobuildRunner: boolean = - !!operationResult.cobuildRunnerId && !operationResult.executedOnThisAgent; - const { stopwatch } = operationResult; + const { _operationMetadataManager: operationMetadataManager } = + operationResult as OperationExecutionRecord; + + let { startTime } = stopwatch; + const { endTime } = stopwatch; - const { startTime, endTime, duration } = 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 ( + operationResult.status !== OperationStatus.FromCache && + operationMetadataManager && + wasCobuilt && + operationResult.nonCachedDurationMs + ) { + duration.cached = stopwatch.duration; + startTime = Math.max(0, endTime - operationResult.nonCachedDurationMs); + duration.uncached = (endTime - startTime) / 1000; + } + + workDuration += stopwatch.duration; - const durationString: string = duration.toFixed(1); + const durationString: string = duration.uncached.toFixed(1); const durationLength: number = durationString.length; if (durationLength > longestDurationLength) { longestDurationLength = durationLength; @@ -176,11 +200,21 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): if (startTime < allStart) { allStart = startTime; } - workDuration += duration; const { associatedPhase } = operation; - durationByPhase.set(associatedPhase, (durationByPhase.get(associatedPhase) || 0) + duration); + if (associatedPhase) { + const previousDuration: ICachedDuration = durationByPhase.get(associatedPhase) ?? { + cached: undefined, + uncached: 0 + }; + const cachedDuration: number | undefined = + duration.cached !== undefined + ? duration.cached + (previousDuration.cached ?? 0) + : previousDuration.cached; + const uncachedDuration: number = duration.uncached + previousDuration.uncached; + durationByPhase.set(associatedPhase, { cached: cachedDuration, uncached: uncachedDuration }); + } data.push({ startTime, @@ -188,7 +222,7 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): durationString, name: operation.name, status: operationResult.status, - isExecutedByOtherCobuildRunner + isExecuteByOtherCobuildRunner: wasCobuilt }); } } @@ -231,8 +265,8 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): let hasCobuildSymbol: boolean = false; function getChartSymbol(record: ITimelineRecord): string { - const { isExecutedByOtherCobuildRunner, status } = record; - if (isExecutedByOtherCobuildRunner && COBUILD_REPORTABLE_STATUSES.has(status)) { + const { isExecuteByOtherCobuildRunner, status } = record; + if (isExecuteByOtherCobuildRunner && COBUILD_REPORTABLE_STATUSES.has(status)) { hasCobuildSymbol = true; return 'C'; } @@ -307,7 +341,10 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): } for (const [phase, duration] of durationByPhase.entries()) { - terminal.writeLine(` ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${duration.toFixed(1)}s`); + const durationString: string = duration.cached + ? `${duration.uncached.toFixed(1)}s, from cache: ${duration.cached.toFixed(1)}s` + : `${duration.uncached.toFixed(1)}s`; + terminal.writeLine(` ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${durationString}`); } } diff --git a/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts b/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts index 7df7332270f..f92f270585a 100644 --- a/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts +++ b/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. */ @@ -56,10 +52,6 @@ export interface IOperationExecutionResult { * The paths to the log files, if applicable. */ readonly logFilePaths: ILogFilePaths | undefined; - /** - * Returns true if this operation was co-built using this machine or cobuilds are disabled, false it was executed on another agent. - */ - readonly executedOnThisAgent: boolean; /** * Gets the hash of the state of all registered inputs to this operation. diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index 08c13e097fd..7908a106e91 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts +++ b/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; @@ -26,7 +27,6 @@ export interface IOperationExecutionManagerOptions { parallelism: number; inputsSnapshot?: IInputsSnapshot; destination?: TerminalWritable; - cobuildConfiguration?: CobuildConfiguration; beforeExecuteOperationAsync?: (operation: OperationExecutionRecord) => Promise; afterExecuteOperationAsync?: (operation: OperationExecutionRecord) => Promise; @@ -110,7 +110,6 @@ export class OperationExecutionManager { this._hasAnyFailures = false; this._hasAnyNonAllowedWarnings = false; this._parallelism = parallelism; - this._cobuildConfiguration = cobuildConfiguration; this._beforeExecuteOperation = beforeExecuteOperation; this._afterExecuteOperation = afterExecuteOperation; @@ -146,8 +145,7 @@ export class OperationExecutionManager { createEnvironment: this._createEnvironmentForOperation, inputsSnapshot, debugMode, - quietMode, - cobuildConfiguration: this._cobuildConfiguration + quietMode }; // Sort the operations by name to ensure consistency and readability. @@ -260,7 +258,9 @@ export class OperationExecutionManager { await this._beforeExecuteOperations?.(this._executionRecords); - const beforeOperationResult: (record: OperationExecutionRecord) => Promise = async ( + // This function is a callback because it may write to the collatedWriter before + // operation.executeAsync returns (and cleans up the writer) + const onOperationCompleteAsync: (record: OperationExecutionRecord) => Promise = async ( record: OperationExecutionRecord ) => { try { @@ -270,6 +270,7 @@ export class OperationExecutionManager { record.error = e; record.status = OperationStatus.Failure; } + this._onOperationComplete(record); }; const onOperationStartAsync: ( @@ -283,8 +284,7 @@ export class OperationExecutionManager { async (record: OperationExecutionRecord) => { await record.executeAsync({ onStart: onOperationStartAsync, - beforeResult: beforeOperationResult, - onResult: this._onOperationComplete.bind(this) + onResult: onOperationCompleteAsync }); }, { @@ -296,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, @@ -332,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) { /** @@ -414,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; @@ -423,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; diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index 4566f6136cb..c103980a2a1 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -28,7 +28,6 @@ import type { IOperationExecutionResult } from './IOperationExecutionResult'; import type { IInputsSnapshot } from '../incremental/InputsSnapshot'; import { RushConstants } from '../RushConstants'; import type { IEnvironment } from '../../utilities/Utilities'; -import type { CobuildConfiguration } from '../../api/CobuildConfiguration'; import { getProjectLogFilePaths, type ILogFilePaths, @@ -41,7 +40,6 @@ export interface IOperationExecutionRecordContext { createEnvironment?: (record: OperationExecutionRecord) => IEnvironment; inputsSnapshot: IInputsSnapshot | undefined; - cobuildConfiguration?: CobuildConfiguration; debugMode: boolean; quietMode: boolean; } @@ -105,11 +103,7 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera */ public readonly consumers: Set = new Set(); - /** - * The stopwatch used to measure the duration of this operation. This is purposefully not - * readonly as we want to override it in the case of a cache hit. - */ - private _stopwatch: Stopwatch = new Stopwatch(); + public readonly stopwatch: Stopwatch = new Stopwatch(); public readonly stdioSummarizer: StdioSummarizer = new StdioSummarizer({ // Allow writing to this object after transforms have been closed. We clean it up manually in a finally block. preventAutoclose: true @@ -170,10 +164,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera return this._context.quietMode; } - public get stopwatch(): Stopwatch { - return this._stopwatch; - } - public get collatedWriter(): CollatedWriter { // Lazy instantiate because the registerTask() call affects display ordering if (!this._collatedWriter) { @@ -204,17 +194,6 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera return TERMINAL_STATUSES.has(this.status); } - public get executedOnThisAgent(): boolean { - if (!this._context.cobuildConfiguration) { - return this.cobuildRunnerId === undefined; - } - return ( - // this can happen if this property is retrieved before `beforeResult` is called. - this.cobuildRunnerId !== undefined && - this._context.cobuildConfiguration?.cobuildRunnerId === this.cobuildRunnerId - ); - } - /** * The current execution status of an operation. Operations start in the 'ready' state, * but can be 'blocked' if an upstream operation failed. It is 'executing' when @@ -380,16 +359,15 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera public async executeAsync({ onStart, - onResult, - beforeResult + onResult }: { onStart: (record: OperationExecutionRecord) => Promise; - beforeResult: (record: OperationExecutionRecord) => Promise; - onResult: (record: OperationExecutionRecord) => Promise | void; + onResult: (record: OperationExecutionRecord) => Promise; }): Promise { - if (this.stopwatch.startTime === undefined) { - this.stopwatch.start(); + if (!this.isTerminal) { + this.stopwatch.reset(); } + this.stopwatch.start(); this.status = OperationStatus.Executing; try { @@ -406,30 +384,16 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera ? OperationStatus.NoOp : OperationStatus.Skipped; } + this.stopwatch.stop(); + // Delegate global state reporting + await onResult(this); } catch (error) { this.status = OperationStatus.Failure; this.error = error; - } finally { - // We may need to clean up and finalize resources (_operationMetadataManager for example needs to be saved by CacheableOperationPlugin) - await beforeResult(this); - if (this.isTerminal) { - this.stopwatch.stop(); - if ( - !this.executedOnThisAgent && - this.nonCachedDurationMs && - this.status !== OperationStatus.FromCache - ) { - const { startTime } = this.stopwatch; - if (startTime) { - this._stopwatch = Stopwatch.fromState({ - // use endtime as it's the more accurate version of when this operation was marked as complete. - startTime, - endTime: startTime + this.nonCachedDurationMs - }); - } - } - } + this.stopwatch.stop(); + // Delegate global state reporting await onResult(this); + } finally { if (this.isTerminal) { this._collatedWriter?.close(); this.stdioSummarizer.close(); diff --git a/libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts b/libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts index 45c45fe312e..b1244a6e0a6 100644 --- a/libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts +++ b/libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts @@ -16,6 +16,7 @@ import { RushConstants } from '../RushConstants'; import type { IOperationStateJson } from './OperationStateFile'; import type { Operation } from './Operation'; +import { type IStopwatchResult, Stopwatch } from '../../utilities/Stopwatch'; /** * @internal @@ -52,6 +53,7 @@ export class OperationMetadataManager { private readonly _logPath: string; private readonly _errorLogPath: string; private readonly _logChunksPath: string; + public wasCobuilt: boolean = false; public constructor(options: IOperationMetadataManagerOptions) { const { @@ -130,13 +132,22 @@ export class OperationMetadataManager { public async tryRestoreAsync({ terminal, terminalProvider, - errorLogPath + errorLogPath, + cobuildContextId, + cobuildRunnerId }: { terminalProvider: ITerminalProvider; terminal: ITerminal; errorLogPath: string; + cobuildContextId?: string; + cobuildRunnerId?: string; }): Promise { await this.stateFile.tryRestoreAsync(); + this.wasCobuilt = + this.stateFile.state?.cobuildContextId !== undefined && + cobuildContextId !== undefined && + this.stateFile.state?.cobuildContextId === cobuildContextId && + this.stateFile.state?.cobuildRunnerId !== cobuildRunnerId; try { const rawLogChunks: string = await FileSystem.readFileAsync(this._logChunksPath); @@ -174,6 +185,18 @@ export class OperationMetadataManager { } } } + + public tryRestoreStopwatch(originalStopwatch: IStopwatchResult): IStopwatchResult { + if (this.wasCobuilt && this.stateFile.state && originalStopwatch.endTime !== undefined) { + const endTime: number = originalStopwatch.endTime; + const startTime: number = Math.max(0, endTime - (this.stateFile.state.nonCachedDurationMs ?? 0)); + return Stopwatch.fromState({ + startTime, + endTime + }); + } + return originalStopwatch; + } } async function restoreFromLogFile(terminal: ITerminal, path: string): Promise { diff --git a/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts b/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts index eb86ab7c421..f085c30fb19 100644 --- a/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts +++ b/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts @@ -12,6 +12,8 @@ import type { import type { IExecutionResult, IOperationExecutionResult } from './IOperationExecutionResult'; import type { Operation } from './Operation'; import { OperationStatus } from './OperationStatus'; +import type { OperationExecutionRecord } from './OperationExecutionRecord'; +import type { IStopwatchResult } from '../../utilities/Stopwatch'; const PLUGIN_NAME: 'OperationResultSummarizerPlugin' = 'OperationResultSummarizerPlugin'; @@ -179,14 +181,23 @@ function writeCondensedSummary( } for (const [operation, operationResult] of operations) { + const { _operationMetadataManager: operationMetadataManager } = + operationResult as OperationExecutionRecord; + const stopwatch: IStopwatchResult = + operationMetadataManager?.tryRestoreStopwatch(operationResult.stopwatch) ?? operationResult.stopwatch; if ( - operationResult.stopwatch.duration !== 0 && + stopwatch.duration !== 0 && operation.runner!.reportTiming && operationResult.status !== OperationStatus.Skipped ) { - const time: string = operationResult.stopwatch.toString(); - const padding: string = ' '.repeat(longestTaskName - operation.name.length); - terminal.writeLine(` ${operation.name}${padding} ${time}`); + const time: string = stopwatch.toString(); + const padding: string = ' '.repeat(longestTaskName - (operation.name || '').length); + const cacheString: string = operationMetadataManager?.wasCobuilt + ? ` (restore ${( + (operationResult.stopwatch.endTime ?? 0) - (operationResult.stopwatch.startTime ?? 0) + ).toFixed(1)}ms)` + : ''; + terminal.writeLine(` ${operation.name}${padding} ${time}${cacheString}`); } else { terminal.writeLine(` ${operation.name}`); } @@ -221,6 +232,8 @@ function writeDetailedSummary( } for (const [operation, operationResult] of operations) { + const { _operationMetadataManager: operationMetadataManager } = + operationResult as OperationExecutionRecord; // Format a header like this // // --[ WARNINGS: f ]------------------------------------[ 5.07 seconds ]-- @@ -231,7 +244,9 @@ function writeDetailedSummary( const leftPartLength: number = 4 + subheadingText.length + 1; // rightPart: " 5.07 seconds ]--" - const time: string = operationResult.stopwatch.toString(); + const stopwatch = + operationMetadataManager?.tryRestoreStopwatch(operationResult.stopwatch) ?? operationResult.stopwatch; + const time: string = stopwatch.toString(); const rightPartLength: number = 1 + time.length + 1 + 3; // middlePart: "]----------------------[" diff --git a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts index 6260d2ae368..c6d932ef11f 100644 --- a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts +++ b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts @@ -3,6 +3,7 @@ // The TaskExecutionManager prints "x.xx seconds" in TestRunner.test.ts.snap; ensure that the Stopwatch timing is deterministic jest.mock('../../../utilities/Utilities'); +jest.mock('../OperationStateFile'); jest.mock('@rushstack/terminal', () => { const originalModule = jest.requireActual('@rushstack/terminal'); @@ -34,6 +35,10 @@ import type { IOperationRunner } from '../IOperationRunner'; import { MockOperationRunner } from './MockOperationRunner'; import type { IExecutionResult, IOperationExecutionResult } from '../IOperationExecutionResult'; import { CollatedTerminalProvider } from '../../../utilities/CollatedTerminalProvider'; +import type { CobuildConfiguration } from '../../../api/CobuildConfiguration'; +import { RushConfigurationProject } from '../../../api/RushConfigurationProject'; +import { IPhase } from '../../../api/CommandLineConfiguration'; +import { IOperationStateJson, OperationStateFile } from '../OperationStateFile'; const mockGetTimeInMs: jest.Mock = jest.fn(); Utilities.getTimeInMs = mockGetTimeInMs; @@ -285,7 +290,7 @@ describe(OperationExecutionManager.name, () => { ); const result: IExecutionResult = await executionManager.executeAsync(); - _printTimeline({ terminal: mockTerminal, result }); + _printTimeline({ terminal: mockTerminal, result, cobuildConfiguration: undefined }); _printOperationStatus(mockTerminal, result); const allMessages: string = mockWritable.getAllOutput(); expect(allMessages).toContain('Build step 1'); @@ -294,4 +299,107 @@ describe(OperationExecutionManager.name, () => { }); }); }); + + describe('Cobuild logging', () => { + beforeEach(() => { + let mockTimeInMs: number = 0; + mockGetTimeInMs.mockImplementation(() => { + mockTimeInMs += 10_000; + return mockTimeInMs; + }); + }); + function createExecutionManager( + executionManagerOptions: IOperationExecutionManagerOptions, + operationRunnerFactory: (name: string) => IOperationRunner, + phase: IPhase, + project: RushConfigurationProject + ): OperationExecutionManager { + const operation: Operation = new Operation({ + runner: operationRunnerFactory('operation'), + logFilenameIdentifier: 'operation', + phase, + project + }); + + const operation2: Operation = new Operation({ + runner: operationRunnerFactory('operation2'), + logFilenameIdentifier: 'operation2', + phase, + project + }); + + return new OperationExecutionManager(new Set([operation, operation2]), { + afterExecuteOperationAsync: async (operation) => { + if (!operation._operationMetadataManager) { + throw new Error('OperationMetadataManager is not defined'); + } + // Mock the readonly state property. + (operation._operationMetadataManager as any).stateFile = { + state: { + cobuildContextId: '123', + cobuildRunnerId: '456', + nonCachedDurationMs: 15_000 + } + } as unknown as OperationStateFile; + operation._operationMetadataManager.wasCobuilt = true; + }, + ...executionManagerOptions + }); + } + it('logs cobuilt operations correctly with --timeline option', async () => { + executionManager = createExecutionManager( + executionManagerOptions, + (name) => + new MockOperationRunner( + `${name} (success)`, + async () => { + return OperationStatus.Success; + }, + /* warningsAreAllowed */ true + ), + { name: 'my-name' } as unknown as IPhase, + {} as unknown as RushConfigurationProject + ); + + const result: IExecutionResult = await executionManager.executeAsync(); + _printTimeline({ + terminal: mockTerminal, + result, + cobuildConfiguration: { + cobuildRunnerId: '123', + cobuildContextId: '123' + } as unknown as CobuildConfiguration + }); + _printOperationStatus(mockTerminal, result); + expect(mockWritable.getFormattedChunks()).toMatchSnapshot(); + }); + it('logs warnings correctly with --timeline option', async () => { + executionManager = createExecutionManager( + executionManagerOptions, + (name) => + new MockOperationRunner(`${name} (success with warnings)`, async (terminal: CollatedTerminal) => { + terminal.writeStdoutLine('Build step 1\n'); + terminal.writeStdoutLine('Warning: step 1 succeeded with warnings\n'); + return OperationStatus.SuccessWithWarning; + }), + { name: 'my-name' } as unknown as IPhase, + {} as unknown as RushConfigurationProject + ); + + const result: IExecutionResult = await executionManager.executeAsync(); + _printTimeline({ + terminal: mockTerminal, + result, + cobuildConfiguration: { + cobuildRunnerId: '123', + cobuildContextId: '123' + } as unknown as CobuildConfiguration + }); + _printOperationStatus(mockTerminal, result); + const allMessages: string = mockWritable.getAllOutput(); + expect(allMessages).toContain('Build step 1'); + expect(allMessages).toContain('Warning: step 1 succeeded with warnings'); + expect(mockWritable.getFormattedChunks()).toMatchSnapshot(); + }); + }); }); diff --git a/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap b/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap index 3446fd2adb0..405cb0cea62 100644 --- a/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap +++ b/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap @@ -1,5 +1,357 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP +exports[`OperationExecutionManager Cobuild logging logs cobuilt operations correctly with --timeline option 1`] = ` +Array [ + Object { + "kind": "O", + "text": "Selected 2 operations: +", + }, + Object { + "kind": "O", + "text": " operation (success) +", + }, + Object { + "kind": "O", + "text": " operation2 (success) +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "Executing a maximum of 1 simultaneous processes... +", + }, + Object { + "kind": "O", + "text": " +[gray]==[[default] [cyan]operation2 (success)[default] [gray]]=========================================[[default] [white]1 of 2[default] [gray]]==[default] +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "[green]\\"operation2 (success)\\" completed successfully in 15.00 seconds.[default] +", + }, + Object { + "kind": "O", + "text": " +[gray]==[[default] [cyan]operation (success)[default] [gray]]==========================================[[default] [white]2 of 2[default] [gray]]==[default] +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "[green]\\"operation (success)\\" completed successfully in 15.00 seconds.[default] +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "========================================================================================== +", + }, + Object { + "kind": "O", + "text": "[cyan]operation2 (success)[default] [gray][default][green]CCCCCCCCCCCCCCCCCCCCCCCCCCC[default][gray]------------------------------------[default] [white]15.0s[default] +", + }, + Object { + "kind": "O", + "text": "[cyan] operation (success)[default] [gray]-----------------------------------[default][green]CCCCCCCCCCCCCCCCCCCCCCCCCCCC[default][gray][default] [white]15.0s[default] +", + }, + Object { + "kind": "O", + "text": "========================================================================================== +", + }, + Object { + "kind": "O", + "text": "LEGEND: Total Work: 20.0s +", + }, + Object { + "kind": "O", + "text": " [#] Success [!] Failed/warnings [%] Skipped/cached/no-op Wall Clock: 35.0s +", + }, + Object { + "kind": "O", + "text": " [C] Cobuild Max Parallelism Used: 1 +", + }, + Object { + "kind": "O", + "text": " Avg Parallelism Used: 0.6 +", + }, + Object { + "kind": "O", + "text": "BY PHASE: +", + }, + Object { + "kind": "O", + "text": " [cyan] my-name[default] 30.0s, from cache: 20.0s +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": " + + +", + }, + Object { + "kind": "O", + "text": "[gray]==[[default] [green]SUCCESS: 2 operations[default] [gray]]====================================================[default] + +", + }, + Object { + "kind": "O", + "text": "These operations completed successfully: +", + }, + Object { + "kind": "O", + "text": " operation (success) 15.00 seconds (restore 10000.0ms) +", + }, + Object { + "kind": "O", + "text": " operation2 (success) 15.00 seconds (restore 10000.0ms) +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": " +", + }, +] +`; + +exports[`OperationExecutionManager Cobuild logging logs warnings correctly with --timeline option 1`] = ` +Array [ + Object { + "kind": "O", + "text": "Selected 2 operations: +", + }, + Object { + "kind": "O", + "text": " operation (success with warnings) +", + }, + Object { + "kind": "O", + "text": " operation2 (success with warnings) +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "Executing a maximum of 1 simultaneous processes... +", + }, + Object { + "kind": "O", + "text": " +[gray]==[[default] [cyan]operation2 (success with warnings)[default] [gray]]===========================[[default] [white]1 of 2[default] [gray]]==[default] +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "Build step 1 + +", + }, + Object { + "kind": "O", + "text": "Warning: step 1 succeeded with warnings + +", + }, + Object { + "kind": "E", + "text": "[yellow]\\"operation2 (success with warnings)\\" completed with warnings in 15.00 seconds.[default] +", + }, + Object { + "kind": "O", + "text": " +[gray]==[[default] [cyan]operation (success with warnings)[default] [gray]]============================[[default] [white]2 of 2[default] [gray]]==[default] +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "Build step 1 + +", + }, + Object { + "kind": "O", + "text": "Warning: step 1 succeeded with warnings + +", + }, + Object { + "kind": "E", + "text": "[yellow]\\"operation (success with warnings)\\" completed with warnings in 15.00 seconds.[default] +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "========================================================================================== +", + }, + Object { + "kind": "O", + "text": "[cyan]operation2 (success with warnings)[default] [gray][default][yellow]CCCCCCCCCCCCCCCCCCCCC[default][gray]----------------------------[default] [white]15.0s[default] +", + }, + Object { + "kind": "O", + "text": "[cyan] operation (success with warnings)[default] [gray]---------------------------[default][yellow]CCCCCCCCCCCCCCCCCCCCCC[default][gray][default] [white]15.0s[default] +", + }, + Object { + "kind": "O", + "text": "========================================================================================== +", + }, + Object { + "kind": "O", + "text": "LEGEND: Total Work: 20.0s +", + }, + Object { + "kind": "O", + "text": " [#] Success [!] Failed/warnings [%] Skipped/cached/no-op Wall Clock: 35.0s +", + }, + Object { + "kind": "O", + "text": " [C] Cobuild Max Parallelism Used: 1 +", + }, + Object { + "kind": "O", + "text": " Avg Parallelism Used: 0.6 +", + }, + Object { + "kind": "O", + "text": "BY PHASE: +", + }, + Object { + "kind": "O", + "text": " [cyan] my-name[default] 30.0s, from cache: 20.0s +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": " + + +", + }, + Object { + "kind": "O", + "text": "[gray]==[[default] [yellow]SUCCESS WITH WARNINGS: 2 operations[default] [gray]]======================================[default] + +", + }, + Object { + "kind": "O", + "text": "[gray]--[[default] [yellow]WARNING: operation (success with warnings)[default] [gray]]------------[[default] [white]15.00 seconds[default] [gray]]--[default] + +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": "[gray]--[[default] [yellow]WARNING: operation2 (success with warnings)[default] [gray]]-----------[[default] [white]15.00 seconds[default] [gray]]--[default] + +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "O", + "text": " +", + }, + Object { + "kind": "E", + "text": "[yellow]Operations succeeded with warnings. +[default] +", + }, +] +`; + exports[`OperationExecutionManager Error logging printedStderrAfterError 1`] = ` Array [ Object { From 570d43faef9e5ef2b9ef826291cead0c229a5911 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 3 Jan 2025 09:32:00 -0700 Subject: [PATCH 22/29] fix lint warnings Signed-off-by: Aramis Sennyey --- .../OperationResultSummarizerPlugin.ts | 2 +- .../test/OperationExecutionManager.test.ts | 30 +++++++++---------- 2 files changed, 16 insertions(+), 16 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts b/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts index f085c30fb19..296b15b09d5 100644 --- a/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts +++ b/libraries/rush-lib/src/logic/operations/OperationResultSummarizerPlugin.ts @@ -244,7 +244,7 @@ function writeDetailedSummary( const leftPartLength: number = 4 + subheadingText.length + 1; // rightPart: " 5.07 seconds ]--" - const stopwatch = + const stopwatch: IStopwatchResult = operationMetadataManager?.tryRestoreStopwatch(operationResult.stopwatch) ?? operationResult.stopwatch; const time: string = stopwatch.toString(); const rightPartLength: number = 1 + time.length + 1 + 3; diff --git a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts index c6d932ef11f..e03e9d15ac1 100644 --- a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts +++ b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts @@ -36,9 +36,9 @@ import { MockOperationRunner } from './MockOperationRunner'; import type { IExecutionResult, IOperationExecutionResult } from '../IOperationExecutionResult'; import { CollatedTerminalProvider } from '../../../utilities/CollatedTerminalProvider'; import type { CobuildConfiguration } from '../../../api/CobuildConfiguration'; -import { RushConfigurationProject } from '../../../api/RushConfigurationProject'; -import { IPhase } from '../../../api/CommandLineConfiguration'; -import { IOperationStateJson, OperationStateFile } from '../OperationStateFile'; +import type { RushConfigurationProject } from '../../../api/RushConfigurationProject'; +import type { IPhase } from '../../../api/CommandLineConfiguration'; +import type { OperationStateFile } from '../OperationStateFile'; const mockGetTimeInMs: jest.Mock = jest.fn(); Utilities.getTimeInMs = mockGetTimeInMs; @@ -302,14 +302,14 @@ describe(OperationExecutionManager.name, () => { describe('Cobuild logging', () => { beforeEach(() => { - let mockTimeInMs: number = 0; + let mockCobuildTimeInMs: number = 0; mockGetTimeInMs.mockImplementation(() => { - mockTimeInMs += 10_000; - return mockTimeInMs; + mockCobuildTimeInMs += 10_000; + return mockCobuildTimeInMs; }); }); - function createExecutionManager( - executionManagerOptions: IOperationExecutionManagerOptions, + function createCobuildExecutionManager( + cobuildExecutionManagerOptions: IOperationExecutionManagerOptions, operationRunnerFactory: (name: string) => IOperationRunner, phase: IPhase, project: RushConfigurationProject @@ -329,25 +329,25 @@ describe(OperationExecutionManager.name, () => { }); return new OperationExecutionManager(new Set([operation, operation2]), { - afterExecuteOperationAsync: async (operation) => { - if (!operation._operationMetadataManager) { + afterExecuteOperationAsync: async (record) => { + if (!record._operationMetadataManager) { throw new Error('OperationMetadataManager is not defined'); } // Mock the readonly state property. - (operation._operationMetadataManager as any).stateFile = { + (record._operationMetadataManager as unknown as Record).stateFile = { state: { cobuildContextId: '123', cobuildRunnerId: '456', nonCachedDurationMs: 15_000 } } as unknown as OperationStateFile; - operation._operationMetadataManager.wasCobuilt = true; + record._operationMetadataManager.wasCobuilt = true; }, - ...executionManagerOptions + ...cobuildExecutionManagerOptions }); } it('logs cobuilt operations correctly with --timeline option', async () => { - executionManager = createExecutionManager( + executionManager = createCobuildExecutionManager( executionManagerOptions, (name) => new MockOperationRunner( @@ -374,7 +374,7 @@ describe(OperationExecutionManager.name, () => { expect(mockWritable.getFormattedChunks()).toMatchSnapshot(); }); it('logs warnings correctly with --timeline option', async () => { - executionManager = createExecutionManager( + executionManager = createCobuildExecutionManager( executionManagerOptions, (name) => new MockOperationRunner(`${name} (success with warnings)`, async (terminal: CollatedTerminal) => { From 462c36df29d6aff4620c7348f71dfa7bfab81bb0 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 3 Jan 2025 09:37:29 -0700 Subject: [PATCH 23/29] remove 1 more hard coded wasCobuilt calculation Signed-off-by: Aramis Sennyey --- .../rush-lib/src/cli/scriptActions/PhasedScriptAction.ts | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts index c3a56d862c0..bc4482fd3e1 100644 --- a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts +++ b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts @@ -1003,18 +1003,13 @@ export class PhasedScriptAction extends BaseScriptAction { const { _operationMetadataManager: operationMetadataManager } = operationResult as OperationExecutionRecord; - const metadataState: IOperationStateJson | undefined = operationMetadataManager?.stateFile.state; const { startTime, endTime } = operationResult.stopwatch; - const wasExecutedOnThisMachine: boolean = cobuildConfiguration?.cobuildFeatureEnabled - ? metadataState?.cobuildContextId === cobuildConfiguration?.cobuildContextId && - metadataState?.cobuildRunnerId === cobuildConfiguration?.cobuildRunnerId - : true; jsonOperationResults[operation.name!] = { startTimestampMs: startTime, endTimestampMs: endTime, nonCachedDurationMs: operationResult.nonCachedDurationMs, - wasExecutedOnThisMachine, + wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt ?? false, result: operationResult.status, dependencies: Array.from(getNonSilentDependencies(operation)).sort() }; From fb06b5e042dc07db3782cd3e45a61da9411275af Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 3 Jan 2025 09:54:59 -0700 Subject: [PATCH 24/29] fix more lint issues + revert stopwatch changes Signed-off-by: Aramis Sennyey --- libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts | 3 +-- .../rush-lib/src/logic/operations/OperationExecutionRecord.ts | 3 +-- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts index bc4482fd3e1..550724fb8e9 100644 --- a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts +++ b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts @@ -59,7 +59,6 @@ import { getVariantAsync, VARIANT_PARAMETER } from '../../api/Variants'; import { Selection } from '../../logic/Selection'; import { NodeDiagnosticDirPlugin } from '../../logic/operations/NodeDiagnosticDirPlugin'; import { DebugHashesPlugin } from '../../logic/operations/DebugHashesPlugin'; -import type { IOperationStateJson } from '../../logic/operations/OperationStateFile'; /** * Constructor parameters for PhasedScriptAction. @@ -901,7 +900,7 @@ export class PhasedScriptAction extends BaseScriptAction { executionManagerOptions ); - const { isInitial, isWatch, cobuildConfiguration } = options.executeOperationsContext; + const { isInitial, isWatch } = options.executeOperationsContext; let success: boolean = false; let result: IExecutionResult | undefined; diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index c103980a2a1..adbdc74427d 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -384,19 +384,18 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera ? OperationStatus.NoOp : OperationStatus.Skipped; } - this.stopwatch.stop(); // Delegate global state reporting await onResult(this); } catch (error) { this.status = OperationStatus.Failure; this.error = error; - this.stopwatch.stop(); // Delegate global state reporting await onResult(this); } finally { if (this.isTerminal) { this._collatedWriter?.close(); this.stdioSummarizer.close(); + this.stopwatch.stop(); } } } From ea0d8c6210f875aea79b3ad5f971ab0c67f9c26f Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Fri, 3 Jan 2025 11:28:28 -0700 Subject: [PATCH 25/29] revert stopwatch back Signed-off-by: Aramis Sennyey --- .../src/logic/operations/OperationExecutionRecord.ts | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index adbdc74427d..f0111b28a15 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -384,18 +384,21 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera ? 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(); } } } From 31047c1c71d0f36ad34f0fae8a927986c7589ba3 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Wed, 5 Mar 2025 09:41:06 -0500 Subject: [PATCH 26/29] fix merge issue Signed-off-by: Aramis Sennyey --- .../src/logic/operations/test/OperationExecutionManager.test.ts | 2 -- 1 file changed, 2 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts index e03e9d15ac1..055e0eb5969 100644 --- a/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts +++ b/libraries/rush-lib/src/logic/operations/test/OperationExecutionManager.test.ts @@ -36,8 +36,6 @@ import { MockOperationRunner } from './MockOperationRunner'; import type { IExecutionResult, IOperationExecutionResult } from '../IOperationExecutionResult'; import { CollatedTerminalProvider } from '../../../utilities/CollatedTerminalProvider'; import type { CobuildConfiguration } from '../../../api/CobuildConfiguration'; -import type { RushConfigurationProject } from '../../../api/RushConfigurationProject'; -import type { IPhase } from '../../../api/CommandLineConfiguration'; import type { OperationStateFile } from '../OperationStateFile'; const mockGetTimeInMs: jest.Mock = jest.fn(); From 0176f99e33c81bb407dae1eab3f3737edf959069 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Wed, 5 Mar 2025 11:33:26 -0500 Subject: [PATCH 27/29] fix snapshot Signed-off-by: Aramis Sennyey --- .../test/__snapshots__/OperationExecutionManager.test.ts.snap | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap b/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap index 405cb0cea62..deb3e8fe623 100644 --- a/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap +++ b/libraries/rush-lib/src/logic/operations/test/__snapshots__/OperationExecutionManager.test.ts.snap @@ -795,7 +795,7 @@ Array [ }, Object { "kind": "O", - "text": " [cyan] phase[default] 0.2s + "text": " [cyan] phase[default] 0.1s ", }, Object { From fabfa57617d7e31069f3a632e427dff1b09c3e00 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey <159921952+aramissennyeydd@users.noreply.github.com> Date: Wed, 5 Mar 2025 18:05:27 -0500 Subject: [PATCH 28/29] Apply suggestions from code review Co-authored-by: David Michon --- .../cli/scriptActions/PhasedScriptAction.ts | 2 +- .../logic/operations/ConsoleTimelinePlugin.ts | 30 +++++++++---------- 2 files changed, 16 insertions(+), 16 deletions(-) diff --git a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts index 550724fb8e9..d3016dca5eb 100644 --- a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts +++ b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts @@ -1008,7 +1008,7 @@ export class PhasedScriptAction extends BaseScriptAction { startTimestampMs: startTime, endTimestampMs: endTime, nonCachedDurationMs: operationResult.nonCachedDurationMs, - wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt ?? false, + wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt !== true, result: operationResult.status, dependencies: Array.from(getNonSilentDependencies(operation)).sort() }; diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index 159ca52fb40..371d3a4d80e 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -176,9 +176,8 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): } const wasCobuilt: boolean = !!operationMetadataManager?.wasCobuilt; if ( - operationResult.status !== OperationStatus.FromCache && - operationMetadataManager && wasCobuilt && + operationResult.status !== OperationStatus.FromCache && operationResult.nonCachedDurationMs ) { duration.cached = stopwatch.duration; @@ -204,16 +203,18 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): const { associatedPhase } = operation; if (associatedPhase) { - const previousDuration: ICachedDuration = durationByPhase.get(associatedPhase) ?? { - cached: undefined, - uncached: 0 - }; - const cachedDuration: number | undefined = - duration.cached !== undefined - ? duration.cached + (previousDuration.cached ?? 0) - : previousDuration.cached; - const uncachedDuration: number = duration.uncached + previousDuration.uncached; - durationByPhase.set(associatedPhase, { cached: cachedDuration, uncached: uncachedDuration }); + let durationRecord: ICachedDuration = 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({ @@ -341,9 +342,8 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): } for (const [phase, duration] of durationByPhase.entries()) { - const durationString: string = duration.cached - ? `${duration.uncached.toFixed(1)}s, from cache: ${duration.cached.toFixed(1)}s` - : `${duration.uncached.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}`); } } From 2dfa48e3cb42d597c7d4b12f141bf7cfb58dcd47 Mon Sep 17 00:00:00 2001 From: Aramis Sennyey Date: Wed, 5 Mar 2025 18:39:51 -0500 Subject: [PATCH 29/29] fix typedef Signed-off-by: Aramis Sennyey --- .../rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts index 371d3a4d80e..fc7bc901018 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -203,7 +203,7 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): const { associatedPhase } = operation; if (associatedPhase) { - let durationRecord: ICachedDuration = durationByPhase.get(associatedPhase); + let durationRecord: ICachedDuration | undefined = durationByPhase.get(associatedPhase); if (!durationRecord) { durationRecord = { cached: undefined, @@ -342,7 +342,9 @@ export function _printTimeline({ terminal, result }: IPrintTimelineParameters): } for (const [phase, duration] of durationByPhase.entries()) { - const cachedDurationString: string = duration.cached ? `, from cache: ${duration.cached.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}`); }