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/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..bb76fd9a8c1 --- /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 correctly reflected across all agents.", + "type": "none" + } + ], + "packageName": "@microsoft/rush" +} \ No newline at end of file diff --git a/common/reviews/api/rush-lib.api.md b/common/reviews/api/rush-lib.api.md index e423b7768e8..bb74a60c40e 100644 --- a/common/reviews/api/rush-lib.api.md +++ b/common/reviews/api/rush-lib.api.md @@ -584,7 +584,6 @@ export interface _INpmOptionsJson extends IPackageManagerOptionsJsonBase { // @alpha export interface IOperationExecutionResult { - readonly cobuildRunnerId: string | undefined; readonly error: Error | undefined; getStateHash(): string; getStateHashComponents(): ReadonlyArray; @@ -958,11 +957,17 @@ export class _OperationMetadataManager { // (undocumented) readonly stateFile: _OperationStateFile; // (undocumented) - tryRestoreAsync({ terminal, terminalProvider, errorLogPath }: { + tryRestoreAsync({ terminal, terminalProvider, errorLogPath, cobuildContextId, cobuildRunnerId }: { terminalProvider: ITerminalProvider; terminal: ITerminal; errorLogPath: string; + cobuildContextId?: string; + cobuildRunnerId?: string; }): Promise; + // (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 4f02d4f08c3..d3016dca5eb 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; @@ -897,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; @@ -997,14 +1000,15 @@ export class PhasedScriptAction extends BaseScriptAction { continue; } + const { _operationMetadataManager: operationMetadataManager } = + operationResult as OperationExecutionRecord; + const { startTime, endTime } = operationResult.stopwatch; jsonOperationResults[operation.name!] = { startTimestampMs: startTime, endTimestampMs: endTime, nonCachedDurationMs: operationResult.nonCachedDurationMs, - wasExecutedOnThisMachine: - !operationResult.cobuildRunnerId || - operationResult.cobuildRunnerId === cobuildConfiguration?.cobuildRunnerId, + wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt !== true, result: operationResult.status, dependencies: Array.from(getNonSilentDependencies(operation)).sort() }; 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 85f540614ec..fc7bc901018 100644 --- a/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts +++ b/libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts @@ -13,6 +13,7 @@ import type { import type { IExecutionResult } from './IOperationExecutionResult'; import { OperationStatus } from './OperationStatus'; import type { CobuildConfiguration } from '../../api/CobuildConfiguration'; +import type { OperationExecutionRecord } from './OperationExecutionRecord'; const PLUGIN_NAME: 'ConsoleTimelinePlugin' = 'ConsoleTimelinePlugin'; @@ -127,20 +128,25 @@ interface ITimelineRecord { export interface IPrintTimelineParameters { terminal: ITerminal; result: IExecutionResult; - cobuildConfiguration: CobuildConfiguration | undefined; + cobuildConfiguration?: CobuildConfiguration; +} + +interface ICachedDuration { + cached?: number; + uncached: number; } /** * Print a more detailed timeline and analysis of CPU usage for the build. * @internal */ -export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrintTimelineParameters): void { +export function _printTimeline({ terminal, result }: IPrintTimelineParameters): void { // // Gather the operation records we'll be displaying. Do some inline max() // finding to reduce the number of times we need to loop through operations. // - const durationByPhase: Map = new Map(); + const durationByPhase: Map = new Map(); const data: ITimelineRecord[] = []; let longestNameLength: number = 0; @@ -155,17 +161,33 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin } const { stopwatch } = operationResult; + const { _operationMetadataManager: operationMetadataManager } = + operationResult as OperationExecutionRecord; + + let { startTime } = stopwatch; + const { endTime } = stopwatch; - const { startTime, endTime } = stopwatch; + const duration: ICachedDuration = { cached: undefined, uncached: stopwatch.duration }; if (startTime && endTime) { const nameLength: number = operation.name?.length || 0; if (nameLength > longestNameLength) { longestNameLength = nameLength; } + const wasCobuilt: boolean = !!operationMetadataManager?.wasCobuilt; + if ( + wasCobuilt && + operationResult.status !== OperationStatus.FromCache && + operationResult.nonCachedDurationMs + ) { + duration.cached = stopwatch.duration; + startTime = Math.max(0, endTime - operationResult.nonCachedDurationMs); + duration.uncached = (endTime - startTime) / 1000; + } + + workDuration += stopwatch.duration; - const { duration } = stopwatch; - const durationString: string = duration.toFixed(1); + const durationString: string = duration.uncached.toFixed(1); const durationLength: number = durationString.length; if (durationLength > longestDurationLength) { longestDurationLength = durationLength; @@ -177,11 +199,23 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin if (startTime < allStart) { allStart = startTime; } - workDuration += duration; const { associatedPhase } = operation; - durationByPhase.set(associatedPhase, (durationByPhase.get(associatedPhase) || 0) + duration); + if (associatedPhase) { + let durationRecord: ICachedDuration | undefined = durationByPhase.get(associatedPhase); + if (!durationRecord) { + durationRecord = { + cached: undefined, + uncached: 0 + }; + durationByPhase.set(associatedPhase, durationRecord); + } + if (duration.cached !== undefined) { + durationRecord.cached = (durationRecord.cached ?? 0) + duration.cached; + } + durationRecord.uncached += duration.uncached; + } data.push({ startTime, @@ -189,9 +223,7 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin durationString, name: operation.name, status: operationResult.status, - isExecuteByOtherCobuildRunner: - !!operationResult.cobuildRunnerId && - operationResult.cobuildRunnerId !== cobuildConfiguration?.cobuildRunnerId + isExecuteByOtherCobuildRunner: wasCobuilt }); } } @@ -310,7 +342,11 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin } for (const [phase, duration] of durationByPhase.entries()) { - terminal.writeLine(` ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${duration.toFixed(1)}s`); + const cachedDurationString: string = duration.cached + ? `, from cache: ${duration.cached.toFixed(1)}s` + : ''; + const durationString: string = `${duration.uncached.toFixed(1)}s${cachedDurationString}`; + terminal.writeLine(` ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${durationString}`); } } diff --git a/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts b/libraries/rush-lib/src/logic/operations/IOperationExecutionResult.ts index 97fd565404b..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. */ diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts index 7908bb3fc40..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; @@ -295,8 +296,8 @@ export class OperationExecutionManager { const status: OperationStatus = this._hasAnyFailures ? OperationStatus.Failure : this._hasAnyNonAllowedWarnings - ? OperationStatus.SuccessWithWarning - : OperationStatus.Success; + ? OperationStatus.SuccessWithWarning + : OperationStatus.Success; return { operationResults: this._executionRecords, @@ -331,7 +332,9 @@ export class OperationExecutionManager { * Handles the result of the operation and propagates any relevant effects. */ private _onOperationComplete(record: OperationExecutionRecord): void { - const { runner, name, status, silent } = record; + const { runner, name, status, silent, _operationMetadataManager: operationMetadataManager } = record; + const stopwatch: IStopwatchResult = + operationMetadataManager?.tryRestoreStopwatch(record.stopwatch) || record.stopwatch; switch (status) { /** @@ -413,7 +416,7 @@ export class OperationExecutionManager { case OperationStatus.Success: { if (!silent) { record.collatedWriter.terminal.writeStdoutLine( - Colorize.green(`"${name}" completed successfully in ${record.stopwatch.toString()}.`) + Colorize.green(`"${name}" completed successfully in ${stopwatch.toString()}.`) ); } break; @@ -422,7 +425,7 @@ export class OperationExecutionManager { case OperationStatus.SuccessWithWarning: { if (!silent) { record.collatedWriter.terminal.writeStderrLine( - Colorize.yellow(`"${name}" completed with warnings in ${record.stopwatch.toString()}.`) + Colorize.yellow(`"${name}" completed with warnings in ${stopwatch.toString()}.`) ); } this._hasAnyNonAllowedWarnings = this._hasAnyNonAllowedWarnings || !runner.warningsAreAllowed; diff --git a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts index 59fff7b38ed..f0111b28a15 100644 --- a/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts +++ b/libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts @@ -24,15 +24,15 @@ import { OperationMetadataManager } from './OperationMetadataManager'; import type { IPhase } from '../../api/CommandLineConfiguration'; import type { RushConfigurationProject } from '../../api/RushConfigurationProject'; import { CollatedTerminalProvider } from '../../utilities/CollatedTerminalProvider'; +import type { IOperationExecutionResult } from './IOperationExecutionResult'; +import type { IInputsSnapshot } from '../incremental/InputsSnapshot'; +import { RushConstants } from '../RushConstants'; +import type { IEnvironment } from '../../utilities/Utilities'; import { getProjectLogFilePaths, type ILogFilePaths, initializeProjectLogFilesAsync } from './ProjectLogWritable'; -import type { IOperationExecutionResult } from './IOperationExecutionResult'; -import type { IInputsSnapshot } from '../incremental/InputsSnapshot'; -import { RushConstants } from '../RushConstants'; -import type { IEnvironment } from '../../utilities/Utilities'; export interface IOperationExecutionRecordContext { streamCollator: StreamCollator; @@ -381,21 +381,24 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera this.status = this.operation.enabled ? await this.runner.executeAsync(this) : this.runner.isNoOp - ? OperationStatus.NoOp - : OperationStatus.Skipped; + ? OperationStatus.NoOp + : OperationStatus.Skipped; } + // Make sure that the stopwatch is stopped before reporting the result, otherwise endTime is undefined. + this.stopwatch.stop(); // Delegate global state reporting await onResult(this); } catch (error) { this.status = OperationStatus.Failure; this.error = error; + // Make sure that the stopwatch is stopped before reporting the result, otherwise endTime is undefined. + this.stopwatch.stop(); // Delegate global state reporting await onResult(this); } finally { if (this.isTerminal) { this._collatedWriter?.close(); this.stdioSummarizer.close(); - this.stopwatch.stop(); } } } 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..296b15b09d5 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: IStopwatchResult = + 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 2520738854d..055e0eb5969 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,8 @@ 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 type { OperationStateFile } from '../OperationStateFile'; const mockGetTimeInMs: jest.Mock = jest.fn(); Utilities.getTimeInMs = mockGetTimeInMs; @@ -294,4 +297,107 @@ describe(OperationExecutionManager.name, () => { }); }); }); + + describe('Cobuild logging', () => { + beforeEach(() => { + let mockCobuildTimeInMs: number = 0; + mockGetTimeInMs.mockImplementation(() => { + mockCobuildTimeInMs += 10_000; + return mockCobuildTimeInMs; + }); + }); + function createCobuildExecutionManager( + cobuildExecutionManagerOptions: 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 (record) => { + if (!record._operationMetadataManager) { + throw new Error('OperationMetadataManager is not defined'); + } + // Mock the readonly state property. + (record._operationMetadataManager as unknown as Record).stateFile = { + state: { + cobuildContextId: '123', + cobuildRunnerId: '456', + nonCachedDurationMs: 15_000 + } + } as unknown as OperationStateFile; + record._operationMetadataManager.wasCobuilt = true; + }, + ...cobuildExecutionManagerOptions + }); + } + it('logs cobuilt operations correctly with --timeline option', async () => { + executionManager = createCobuildExecutionManager( + 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 = createCobuildExecutionManager( + 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 7492df9711e..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 @@ -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 { @@ -241,7 +593,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 +681,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 +760,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 +770,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 { @@ -443,7 +795,7 @@ Array [ }, Object { "kind": "O", - "text": " [cyan] phase[default] 0.2s + "text": " [cyan] phase[default] 0.1s ", }, Object { @@ -466,7 +818,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] ", }, 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 */