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

aramissennyeydd · 2024-05-07T17:10:26Z

Summary

OperationExecutionRecord is currently only tracking cache restore time for cobuilt operations that are marked as RemoteOperating and are then restored from cache. This is a confusing UX and causes developers + maintainers to have to search across multiple machine logs to determine operation run times. This PR adjusts that to use the nonCachedDurationMs from the state file. This felt like something that #3649 was intending to do or is in a similar vein.

Before:

After:

Details

This overwrites the existing stopwatch for operations that were not cobuilt on the specific agent. It adds a new beforeResult method to OperationExecutionRecord#executeAsync to handle the afterExecuteOperation hook instead of passing that work into the onResult method which ended up receiving running stopwatches and had other assumptions of state (collated terminal not closed). This does add possibly breaking behavior where cobuilds were showing cache times which might be useful, but I don't think those are as useful as having the cobuild time available across all agents. That also has the secondary effect of making the timeline views of all agents much more cohesive - though as we see above they're not the exact same across agents.

How it was tested

I tested this locally using the build-tests/rush-redis-cobuild-plugin-integration-test sandbox repo with 2 runners, confirmed that timings generally matched across the instances. There's about 10ms (rounded up) of difference between the agents, but this already seems much more useful.

Impacted documentation

None

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

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

aramissennyeydd · 2024-05-10T14:08:42Z

Small adjustment to improve the dependency view, previously they were getting smushed into the same time slot, when they should be sequential.

aramissennyeydd · 2024-05-10T14:12:39Z

And a few screen grabs from our internal instance showing the difference from the small adjustment,

Before

After

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

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

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

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

UberMouse · 2024-10-10T03:49:15Z

Any reason this hasn't been merged? It's a real problem trying to work out performance of co-build enabled builds 😬

aramissennyeydd · 2024-10-10T14:28:55Z

@UberMouse Lost track of this, I was waiting on #4755 to get merged so we didn't cause more telemetry skew with this.

iclanton · 2024-10-29T18:16:12Z

@aramissennyeydd - this should be unblocked now.

aramissennyeydd · 2024-12-26T18:34:08Z

@iclanton This should be good for another round of 👀 🙏

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

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

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

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

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

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

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

UberMouse · 2025-04-27T21:57:00Z

Any chance of this getting merged soon?

Co-authored-by: Ian Clanton-Thuon <iclanton@users.noreply.github.com>

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

Co-authored-by: David Michon <dmichon@microsoft.com>

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

aramissennyeydd · 2025-05-05T21:12:49Z

Posted in Zulip for a review, sorry for the slow cycles here - fixed the merge conflict that was here as well

octogonz · 2025-05-07T00:37:18Z

Looks like @iclanton already approved it -- let me see what's up

aramissennyeydd requested review from iclanton, octogonz, apostolisms, D4N14L and dmichon-msft as code owners May 7, 2024 17:10

iclanton approved these changes May 10, 2024

View reviewed changes

libraries/rush-lib/src/logic/operations/ConsoleTimelinePlugin.ts Outdated Show resolved Hide resolved

libraries/rush-lib/src/logic/operations/OperationExecutionManager.ts Outdated Show resolved Hide resolved

iclanton reviewed May 13, 2024

View reviewed changes

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

iclanton previously approved these changes May 13, 2024

View reviewed changes

aramissennyeydd force-pushed the sennyeya/operation-timings branch from 582ef41 to 1da8e9d Compare May 21, 2024 20:12

This was referenced May 24, 2024

[rush] duplicated cobuild telemetry leading to data skew #4737

Closed

[rush] Differentiate remote and local execution in telemetry. #4755

Merged

aramissennyeydd force-pushed the sennyeya/operation-timings branch from 77ffeee to 44b9ff2 Compare December 26, 2024 18:15

dmichon-msft reviewed Dec 26, 2024

View reviewed changes

aramissennyeydd commented Jan 3, 2025

View reviewed changes

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts Show resolved Hide resolved

aramissennyeydd force-pushed the sennyeya/operation-timings branch from 4171584 to 5a426de Compare March 5, 2025 14:41

dmichon-msft reviewed Mar 5, 2025

View reviewed changes

iclanton reviewed Mar 5, 2025

View reviewed changes

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts Outdated Show resolved Hide resolved

aramissennyeydd commented Mar 5, 2025

View reviewed changes

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts Outdated Show resolved Hide resolved

aramissennyeydd commented Mar 5, 2025

View reviewed changes

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts Show resolved Hide resolved

aramissennyeydd mentioned this pull request Mar 5, 2025

[rush] allow Stopwatch to track multiple distinct intervals #5148

Open

aramissennyeydd requested a review from iclanton March 12, 2025 01:32

aramissennyeydd dismissed iclanton’s stale review via 5c6a68d April 1, 2025 01:25

fix: show cobuild timings for all agents

99024b4

aramissennyeydd and others added 24 commits May 5, 2025 16:51

fix snapshot

3ddde09

fix linting

523e08f

adjust the check to check for cobuild disabled

dd67e3f

make it not async

48e2361

make operation tracking async

bdeffcb

fix binding

77df07b

small adjustments to make the operations look better in timeline view

cad6b5b

Apply suggestions from code review

54d9265

Co-authored-by: Ian Clanton-Thuon <iclanton@users.noreply.github.com>

adjust comment

19f98fd

flip stopwatch usage

41e9cd5

add a comment

088141d

Un-async _onOperationComplete.

c1d2f2d

un-async onOperationComplete

e6f821e

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

fix build

93e2aa8

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

rebase fixes

c4306ea

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

address PR feedback, move cobuild state to operation metadata manager

f2c3c26

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

fix lint warnings

570d43f

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

remove 1 more hard coded wasCobuilt calculation

462c36d

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

fix more lint issues + revert stopwatch changes

fb06b5e

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

revert stopwatch back

ea0d8c6

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

fix merge issue

31047c1

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

fix snapshot

0176f99

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

Apply suggestions from code review

fabfa57

Co-authored-by: David Michon <dmichon@microsoft.com>

fix typedef

2dfa48e

Signed-off-by: Aramis Sennyey <aramissennyeydd@users.noreply.github.com>

aramissennyeydd force-pushed the sennyeya/operation-timings branch from 5c6a68d to 2dfa48e Compare May 5, 2025 21:06

iclanton approved these changes May 7, 2025

View reviewed changes

iclanton merged commit 42c97ef into microsoft:main May 7, 2025
5 checks passed

github-project-automation bot moved this from In Progress to Closed in Bug Triage May 7, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

aramissennyeydd commented May 7, 2024

aramissennyeydd commented May 10, 2024

aramissennyeydd commented May 10, 2024 •

edited

Loading

UberMouse commented Oct 10, 2024

aramissennyeydd commented Oct 10, 2024

iclanton commented Oct 29, 2024

aramissennyeydd commented Dec 26, 2024

UberMouse commented Apr 27, 2025

aramissennyeydd commented May 5, 2025

octogonz commented May 7, 2025

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

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

Conversation

aramissennyeydd commented May 7, 2024

Summary

Before:

After:

Details

How it was tested

Impacted documentation

aramissennyeydd commented May 10, 2024

aramissennyeydd commented May 10, 2024 • edited Loading

Before

After

UberMouse commented Oct 10, 2024

aramissennyeydd commented Oct 10, 2024

iclanton commented Oct 29, 2024

aramissennyeydd commented Dec 26, 2024

UberMouse commented Apr 27, 2025

aramissennyeydd commented May 5, 2025

octogonz commented May 7, 2025

aramissennyeydd commented May 10, 2024 •

edited

Loading