10000 fix(timeline,cobuilds): cobuilt operations should reflect the cobuild… · lwsinclair/rushstack@42c97ef · GitHub
[go: up one dir, main page]
Skip to content

Commit 42c97ef

Browse files
aramissennyeyddiclantondmichon-msft
authored
fix(timeline,cobuilds): cobuilt operations should reflect the cobuild time and not cache restore time (microsoft#4680)
* fix: show cobuild timings for all agents * stopwatch timing isn't correct * cleanup * fixing when cache is flushed to disk * add changeset * fix snapshot * fix linting * adjust the check to check for cobuild disabled * make it not async * make operation tracking async * fix binding * small adjustments to make the operations look better in timeline view * Apply suggestions from code review Co-authored-by: Ian Clanton-Thuon <iclanton@users.noreply.github.com> * adjust comment * flip stopwatch usage * add a comment * Un-async _onOperationComplete. * un-async onOperationComplete Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * fix build Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * rebase fixes Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * address PR feedback, move cobuild state to operation metadata manager Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * fix lint warnings Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * remove 1 more hard coded wasCobuilt calculation Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * fix more lint issues + revert stopwatch changes Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * revert stopwatch back Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * fix merge issue Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * fix snapshot Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> * Apply suggestions from code review Co-authored-by: David Michon <dmichon@microsoft.com> * fix typedef Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> --------- Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> Co-authored-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com> Co-authored-by: Ian Clanton-Thuon <iclanton@users.noreply.github.com> Co-authored-by: David Michon <dmichon@microsoft.com>
1 parent 2aa34a1 commit 42c97ef

File tree

14 files changed

+615
-55
lines changed

14 files changed

+615
-55
lines changed

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

Lines changed: 1 addition & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -4,16 +4,13 @@
44
{
55
"operationName": "_phase:build",
66
"outputFolderNames": ["dist"],
7-
"allowCobuildOrchestration": true,
8-
"disableBuildCacheForOperation": true,
97
"sharding": {
108
"count": 75
119
}
1210
},
1311
{
1412
"operationName": "_phase:build:shard",
15-
"weight": 10,
16-
"allowCobuildOrchestration": true
13+
"weight": 10
1714
}
1815
]
1916
}

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

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
{
2+
"changes": [
3+
{
4+
"packageName": "@microsoft/rush",
5+
"comment": "Operations that were cobuilt now have the cobuild time correctly reflected across all agents.",
6+
"type": "none"
7+
}
8+
],
9+
"packageName": "@microsoft/rush"
10+
}

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

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -584,7 +584,6 @@ export interface _INpmOptionsJson extends IPackageManagerOptionsJsonBase {
584584

585585
// @alpha
586586
export interface IOperationExecutionResult {
587-
readonly cobuildRunnerId: string | undefined;
588587
readonly error: Error | undefined;
589588
getStateHash(): string;
590589
getStateHashComponents(): ReadonlyArray<string>;
@@ -958,11 +957,17 @@ export class _OperationMetadataManager {
958957
// (undocumented)
959958
readonly stateFile: _OperationStateFile;
960959
// (undocumented)
961-
tryRestoreAsync({ terminal, terminalProvider, errorLogPath }: {
960+
tryRestoreAsync({ terminal, terminalProvider, errorLogPath, cobuildContextId, cobuildRunnerId }: {
962961
terminalProvider: ITerminalProvider;
963962
terminal: ITerminal;
964963
errorLogPath: string;
964+
cobuildContextId?: string;
965+
cobuildRunnerId?: string;
965966
}): Promise<void>;
967+
// (undocumented)
968+
tryRestoreStopwatch(originalStopwatch: IStopwatchResult): IStopwatchResult;
969+
// (undocumented)
970+
wasCobuilt: boolean;
966971
}
967972
< 10000 br>
968973
// @internal

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

Lines changed: 11 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -676,7 +676,9 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
676676
` Press <${quitKey}> to gracefully exit.`,
677677
` Press <${toggleWatcherKey}> to ${isPaused ? 'resume' : 'pause'}.`,
678678
` Press <${invalidateKey}> to invalidate all projects.`,
679-
` Press <${changedProjectsOnlyKey}> to ${this._changedProjectsOnly ? 'disable' : 'enable'} changed-projects-only mode (${this._changedProjectsOnly ? 'ENABLED' : 'DISABLED'}).`
679+
` Press <${changedProjectsOnlyKey}> to ${
680+
this._changedProjectsOnly ? 'disable' : 'enable'
681+
} changed-projects-only mode (${this._changedProjectsOnly ? 'ENABLED' : 'DISABLED'}).`
680682
];
681683
if (isPaused) {
682684
promptLines.push(` Press <${buildOnceKey}> to build once.`);
@@ -820,8 +822,9 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
820822
// eslint-disable-next-line no-constant-condition
821823
while (!abortSignal.aborted) {
822824
// On the initial invocation, this promise will return immediately with the full set of projects
823-
const { changedProjects, inputsSnapshot: state } =
824-
await projectWatcher.waitForChangeAsync(onWaitingForChanges);
825+
const { changedProjects, inputsSnapshot: state } = await projectWatcher.waitForChangeAsync(
826+
onWaitingForChanges
827+
);
825828

826829
if (abortSignal.aborted) {
827830
return;
@@ -897,7 +900,7 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
897900
executionManagerOptions
898901
);
899902

900-
const { isInitial, isWatch, cobuildConfiguration } = options.executeOperationsContext;
903+
const { isInitial, isWatch } = options.executeOperationsContext;
901904

902905
let success: boolean = false;
903906
let result: IExecutionResult | undefined;
@@ -997,14 +1000,15 @@ export class PhasedScriptAction extends BaseScriptAction<IPhasedCommandConfig> {
9971000
continue;
9981001
}
9991002

1003+
const { _operationMetadataManager: operationMetadataManager } =
1004+
operationResult as OperationExecutionRecord;
1005+
10001006
const { startTime, endTime } = operationResult.stopwatch;
10011007
jsonOperationResults[operation.name!] = {
10021008
startTimestampMs: startTime,
10031009
endTimestampMs: endTime,
10041010
nonCachedDurationMs: operationResult.nonCachedDurationMs,
1005-
wasExecutedOnThisMachine:
1006-
!operationResult.cobuildRunnerId ||
1007-
operationResult.cobuildRunnerId === cobuildConfiguration?.cobuildRunnerId,
1011+
wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt !== true,
10081012
result: operationResult.status,
10091013
dependencies: Array.from(getNonSilentDependencies(operation)).sort()
10101014
};

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

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -324,7 +324,9 @@ export class CacheableOperationPlugin implements IPhasedCommandPlugin {
324324
await operationMetadataManager?.tryRestoreAsync({
325325
terminalProvider,
326326
terminal: buildCacheTerminal,
327-
errorLogPath
327+
errorLogPath,
328+
cobuildContextId: cobuildConfiguration?.cobuildContextId,
329+
cobuildRunnerId: cobuildConfiguration?.cobuildRunnerId
328330
});
329331
},
330332
{ createLogFile: false }

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

Lines changed: 48 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ import type {
1313
import type { IExecutionResult } from './IOperationExecutionResult';
1414
import { OperationStatus } from './OperationStatus';
1515
import type { CobuildConfiguration } from '../../api/CobuildConfiguration';
16+
import type { OperationExecutionRecord } from './OperationExecutionRecord';
1617

1718
const PLUGIN_NAME: 'ConsoleTimelinePlugin' = 'ConsoleTimelinePlugin';
1819

@@ -127,20 +128,25 @@ interface ITimelineRecord {
127128
export interface IPrintTimelineParameters {
128129
terminal: ITerminal;
129130
result: IExecutionResult;
130-
cobuildConfiguration: CobuildConfiguration | undefined;
131+
cobuildConfiguration?: CobuildConfiguration;
132+
}
133+
134+
interface ICachedDuration {
135+
cached?: number;
136+
uncached: number;
131137
}
132138

133139
/**
134140
* Print a more detailed timeline and analysis of CPU usage for the build.
135141
* @internal
136142
*/
137-
export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrintTimelineParameters): void {
143+
export function _printTimeline({ terminal, result }: IPrintTimelineParameters): void {
138144
//
139145
// Gather the operation records we'll be displaying. Do some inline max()
140146
// finding to reduce the number of times we need to loop through operations.
141147
//
142148

143-
const durationByPhase: Map<IPhase, number> = new Map();
149+
const durationByPhase: Map<IPhase, ICachedDuration> = new Map();
144150

145151
const data: ITimelineRecord[] = [];
146152
let longestNameLength: number = 0;
@@ -155,17 +161,33 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin
155161
}
156162

157163
const { stopwatch } = operationResult;
164+
const { _operationMetadataManager: operationMetadataManager } =
165+
operationResult as OperationExecutionRecord;
166+
167+
let { startTime } = stopwatch;
168+
const { endTime } = stopwatch;
158169

159-
const { startTime, endTime } = stopwatch;
170+
const duration: ICachedDuration = { cached: undefined, uncached: stopwatch.duration };
160171

161172
if (startTime && endTime) {
162173
const nameLength: number = operation.name?.length || 0;
163174
if (nameLength > longestNameLength) {
164175
longestNameLength = nameLength;
165176
}
177+
const wasCobuilt: boolean = !!operationMetadataManager?.wasCobuilt;
178+
if (
179+
wasCobuilt &&
180+
operationResult.status !== OperationStatus.FromCache &&
181+
operationResult.nonCachedDurationMs
182+
) {
183+
duration.cached = stopwatch.duration;
184+
startTime = Math.max(0, endTime - operationResult.nonCachedDurationMs);
185+
duration.uncached = (endTime - startTime) / 1000;
186+
}
187+
188+
workDuration += stopwatch.duration;
166189

167-
const { duration } = stopwatch;
168-
const durationString: string = duration.toFixed(1);
190+
const durationString: string = duration.uncached.toFixed(1);
169191
const durationLength: number = durationString.length;
170192
if (durationLength > longestDurationLength) {
171193
longestDurationLength = durationLength;
@@ -177,21 +199,31 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin
177199
if (startTime < allStart) {
178200
allStart = startTime;
179201
}
180-
workDuration += duration;
181202

182203
const { associatedPhase } = operation;
183204

184-
durationByPhase.set(associatedPhase, (durationByPhase.get(associatedPhase) || 0) + duration);
205+
if (associatedPhase) {
206+
let durationRecord: ICachedDuration | undefined = durationByPhase.get(associatedPhase);
207+
if (!durationRecord) {
208+
durationRecord = {
209+
cached: undefined,
210+
uncached: 0
211+
};
212+
durationByPhase.set(associatedPhase, durationRecord);
213+
}
214+
if (duration.cached !== undefined) {
215+
durationRecord.cached = (durationRecord.cached ?? 0) + duration.cached;
216+
}
217+
durationRecord.uncached += duration.uncached;
218+
}
185219

186220
data.push({
187221
startTime,
188222
endTime,
189223
durationString,
190224
name: operation.name,
191225
status: operationResult.status,
192-
isExecuteByOtherCobuildRunner:
193-
!!operationResult.cobuildRunnerId &&
194-
operationResult.cobuildRunnerId !== cobuildConfiguration?.cobuildRunnerId
226+
isExecuteByOtherCobuildRunner: wasCobuilt
195227
});
196228
}
197229
}
@@ -310,7 +342,11 @@ export function _printTimeline({ terminal, result, cobuildConfiguration }: IPrin
310342
}
311343

312344
for (const [phase, duration] of durationByPhase.entries()) {
313-
terminal.writeLine(` ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${duration.toFixed(1)}s`);
345+
const cachedDurationString: string = duration.cached
346+
? `, from cache: ${duration.cached.toFixed(1)}s`
347+
: '';
348+
const durationString: string = `${duration.uncached.toFixed(1)}s${cachedDurationString}`;
349+
terminal.writeLine(` ${Colorize.cyan(phase.name.padStart(maxPhaseName))} ${durationString}`);
314350
}
315351
}
316352

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

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -44,10 +44,6 @@ export interface IOperationExecutionResult {
4444
* The value indicates the duration of the same operation without cache hit.
4545
*/
4646
readonly nonCachedDurationMs: number | undefined;
47-
/**
48-
* The id of the runner which actually runs the building process in cobuild mode.
49-
*/
50-
readonly cobuildRunnerId: string | undefined;
5147< 10000 div class="diff-text-inner"> /**
5248
* The relative path to the folder that contains operation metadata. This folder will be automatically included in cache entries.
5349
*/

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

Lines changed: 8 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ import { type IOperationExecutionRecordContext, OperationExecutionRecord } from
1919
import type { IExecutionResult } from './IOperationExecutionResult';
2020
import type { IEnvironment } from '../../utilities/Utilities';
2121
import type { IInputsSnapshot } from '../incremental/InputsSnapshot';
22+
import type { IStopwatchResult } from '../../utilities/Stopwatch';
2223

2324
export interface IOperationExecutionManagerOptions {
2425
quietMode: boolean;
@@ -295,8 +296,8 @@ export class OperationExecutionManager {
295296
const status: OperationStatus = this._hasAnyFailures
296297
? OperationStatus.Failure
297298
: this._hasAnyNonAllowedWarnings
298-
? OperationStatus.SuccessWithWarning
299-
: OperationStatus.Success;
299+
? OperationStatus.SuccessWithWarning
300+
: OperationStatus.Success;
300301

301302
return {
302303
operationResults: this._executionRecords,
@@ -331,7 +332,9 @@ export class OperationExecutionManager {
331332
* Handles the result of the operation and propagates any relevant effects.
332333
*/
333334
private _onOperationComplete(record: OperationExecutionRecord): void {
334-
const { runner, name, status, silent } = record;
335+
const { runner, name, status, silent, _operationMetadataManager: operationMetadataManager } = record;
336+
const stopwatch: IStopwatchResult =
337+
operationMetadataManager?.tryRestoreStopwatch(record.stopwatch) || record.stopwatch;
335338

336339
switch (status) {
337340
/**
@@ -413,7 +416,7 @@ export class OperationExecutionManager {
413416
case OperationStatus.Success: {
414417
if (!silent) {
415418
record.collatedWriter.terminal.writeStdoutLine(
416-
Colorize.green(`"${name}" completed successfully in ${record.stopwatch.toString()}.`)
419+
Colorize.green(`"${name}" completed successfully in ${stopwatch.toString()}.`)
417420
);
418421
}
419422
break;
@@ -422,7 +425,7 @@ export class OperationExecutionManager {
422425
case OperationStatus.SuccessWithWarning: {
423426
if (!silent) {
424427
record.collatedWriter.terminal.writeStderrLine(
425-
Colorize.yellow(`"${name}" completed with warnings in ${record.stopwatch.toString()}.`)
428+
Colorize.yellow(`"${name}" completed with warnings in ${stopwatch.toString()}.`)
426429
);
427430
}
428431
this._hasAnyNonAllowedWarnings = this._hasAnyNonAllowedWarnings || !runner.warningsAreAllowed;

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

Lines changed: 10 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -24,15 +24,15 @@ import { OperationMetadataManager } from './OperationMetadataManager';
2424
import type { IPhase } from '../../api/CommandLineConfiguration';
2525
import type { RushConfigurationProject } from '../../api/RushConfigurationProject';
2626
import { CollatedTerminalProvider } from '../../utilities/CollatedTerminalProvider';
27+
import type { IOperationExecutionResult } from './IOperationExecutionResult';
28+
import type { IInputsSnapshot } from '../incremental/InputsSnapshot';
29+
import { RushConstants } from '../RushConstants';
30+
import type { IEnvironment } from '../../utilities/Utilities';
2731
import {
2832
getProjectLogFilePaths,
2933
type ILogFilePaths,
3034
initializeProjectLogFilesAsync
3135
} from './ProjectLogWritable';
32-
import type { IOperationExecutionResult } from './IOperationExecutionResult';
33-
import type { IInputsSnapshot } from '../incremental/InputsSnapshot';
34-
import { RushConstants } from '../RushConstants';
35-
import type { IEnvironment } from '../../utilities/Utilities';
3636

3737
export interface IOperationExecutionRecordContext {
3838
streamCollator: StreamCollator;
@@ -381,21 +381,24 @@ export class OperationExecutionRecord implements IOperationRunnerContext, IOpera
381381
this.status = this.operation.enabled
382382
? await this.runner.executeAsync(this)
383383
: this.runner.isNoOp
384-
? OperationStatus.NoOp
385-
: OperationStatus.Skipped;
384+
? OperationStatus.NoOp
385+
: OperationStatus.Skipped;
386386
}
387+
// Make sure that the stopwatch is stopped before reporting the result, otherwise endTime is undefined.
388+
this.stopwatch.stop();
387389
// Delegate global state reporting
388390
await onResult(this);
389391
} catch (error) {
390392
this.status = OperationStatus.Failure;
391393
this.error = error;
394+
// Make sure that the stopwatch is stopped before reporting the result, otherwise endTime is undefined.
395+
this.stopwatch.stop();
392396
// Delegate global state reporting
393397
await onResult(this);
394398
} finally {
395399
if (this.isTerminal) {
396400
this._collatedWriter?.close();
397401
this.stdioSummarizer.close();
398-
this.stopwatch.stop();
399402
}
400403
}
401404
}

0 commit comments

Comments
 (0)
0