Skip to content

Log yielded time in the Component Track #31563

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Nov 19, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 48 additions & 0 deletions packages/react-reconciler/src/ReactFiberPerformanceTrack.js
Original file line number Diff line number Diff line change
Expand Up @@ -114,6 +114,54 @@ export function logComponentEffect(
}
}

export function logYieldTime(startTime: number, endTime: number): void {
if (supportsUserTiming) {
const yieldDuration = endTime - startTime;
if (yieldDuration < 1) {
// Skip sub-millisecond yields. This happens all the time and is not interesting.
return;
}
Comment on lines +120 to +123
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do these become >=1ms when CPU throttling is turned on?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe for the really slow ones. Depends on the overhead of yielding on the platform I guess.

// Being blocked on CPU is potentially bad so we color it by how long it took.
reusableComponentDevToolDetails.color =
yieldDuration < 5
? 'primary-light'
: yieldDuration < 10
? 'primary'
: yieldDuration < 100
Comment on lines +126 to +130
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How do we decide the numeric value of these thresholds?

Copy link
Collaborator Author

@sebmarkbage sebmarkbage Nov 19, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Originally the render time ones are <1, <10, <100, and above.

This comes from that a typical component should really be less then 1ms. If it's less than 10 you can still comfortably fit the rendering within a frame with some additional overhead but that's still very high for a single component. You can do a lot in 10ms. That still lets you do JS based animations.

Above that you're starting to be unable to do JS animations without dropping frames. Approaching error territory but ideally an event should respond in about 50ms. If on average your click hits in the middle of 100ms, and we yield 50ms after that. Assuming the response renders fast after that, you're still within the range of feeling responsive so it's ok. But that's the very top end.

Above 100ms you're really in error territory. You can no longer be responsive to new input.

The effect ones are more permissive because they are expected to kind of happen in the seams like when you commit a brand new page rather than in the background or continuously. E.g. the animation probably just finished and is about to restart. However, we probably should maybe lower this for Blocking lane because a long commit in blocking lane is also not good because it's likely to maybe happen more repeatedly.

For yields I'm trying to mirror the time coloring of component render. In that case it's something else blocking us so whatever that is has the same constraints as we do. However, it's more likely to have small little 1-5ms yields due to some little timer or something yielding that I increased the minimum number a little bit.

? 'primary-dark'
: 'error';
reusableComponentOptions.start = startTime;
reusableComponentOptions.end = endTime;
performance.measure('Blocked', reusableComponentOptions);
}
}

export function logSuspendedYieldTime(
startTime: number,
endTime: number,
suspendedFiber: Fiber,
): void {
if (supportsUserTiming) {
reusableComponentDevToolDetails.color = 'primary-light';
reusableComponentOptions.start = startTime;
reusableComponentOptions.end = endTime;
performance.measure('Suspended', reusableComponentOptions);
}
}

export function logActionYieldTime(
startTime: number,
endTime: number,
suspendedFiber: Fiber,
): void {
if (supportsUserTiming) {
reusableComponentDevToolDetails.color = 'primary-light';
reusableComponentOptions.start = startTime;
reusableComponentOptions.end = endTime;
performance.measure('Action', reusableComponentOptions);
}
}

export function logBlockingStart(
updateTime: number,
eventTime: number,
Expand Down
32 changes: 31 additions & 1 deletion packages/react-reconciler/src/ReactFiberWorkLoop.js
Original file line number Diff line number Diff line change
Expand Up @@ -79,6 +79,9 @@ import {
logCommitPhase,
logPaintYieldPhase,
logPassiveCommitPhase,
logYieldTime,
logActionYieldTime,
logSuspendedYieldTime,
} from './ReactFiberPerformanceTrack';

import {
Expand Down Expand Up @@ -264,6 +267,9 @@ import {
stopProfilerTimerIfRunningAndRecordIncompleteDuration,
markUpdateAsRepeat,
trackSuspendedTime,
startYieldTimer,
yieldStartTime,
yieldReason,
} from './ReactProfilerTimer';
import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack';

Expand Down Expand Up @@ -351,7 +357,7 @@ let workInProgress: Fiber | null = null;
// The lanes we're rendering
let workInProgressRootRenderLanes: Lanes = NoLanes;

opaque type SuspendedReason = 0 | 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9;
export opaque type SuspendedReason = 0 | 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9;
const NotSuspended: SuspendedReason = 0;
const SuspendedOnError: SuspendedReason = 1;
const SuspendedOnData: SuspendedReason = 2;
Expand Down Expand Up @@ -915,6 +921,24 @@ export function performWorkOnRoot(
throw new Error('Should not already be working.');
}

if (enableProfilerTimer && enableComponentPerformanceTrack) {
if (workInProgressRootRenderLanes !== NoLanes && workInProgress !== null) {
const yieldedFiber = workInProgress;
// We've returned from yielding to the event loop. Let's log the time it took.
const yieldEndTime = now();
switch (yieldReason) {
case SuspendedOnData:
logSuspendedYieldTime(yieldStartTime, yieldEndTime, yieldedFiber);
break;
case SuspendedOnAction:
logActionYieldTime(yieldStartTime, yieldEndTime, yieldedFiber);
break;
default:
logYieldTime(yieldStartTime, yieldEndTime);
}
}
}

// We disable time-slicing in some cases: if the work has been CPU-bound
// for too long ("expired" work, to prevent starvation), or we're in
// sync-updates-by-default mode.
Expand Down Expand Up @@ -956,6 +980,12 @@ export function performWorkOnRoot(
const didAttemptEntireTree = false;
markRootSuspended(root, lanes, NoLane, didAttemptEntireTree);
}
if (enableProfilerTimer && enableComponentPerformanceTrack) {
// We're about to yield. Let's keep track of how long we yield to the event loop.
// We also stash the suspended reason at the time we yielded since it might have
// changed when we resume such as when it gets pinged.
startYieldTimer(workInProgressSuspendedReason);
}
break;
} else {
let renderEndTime = 0;
Expand Down
13 changes: 13 additions & 0 deletions packages/react-reconciler/src/ReactProfilerTimer.js
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@

import type {Fiber} from './ReactInternalTypes';

import type {SuspendedReason} from './ReactFiberWorkLoop';

import type {Lane, Lanes} from './ReactFiberLane';
import {
isTransitionLane,
Expand Down Expand Up @@ -58,6 +60,17 @@ export let transitionEventType: null | string = null; // Event type of the first
export let transitionEventIsRepeat: boolean = false;
export let transitionSuspendedTime: number = -1.1;

export let yieldReason: SuspendedReason = (0: any);
export let yieldStartTime: number = -1.1; // The time when we yielded to the event loop

export function startYieldTimer(reason: SuspendedReason) {
if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
return;
}
yieldStartTime = now();
yieldReason = reason;
}

export function startUpdateTimerByLane(lane: Lane): void {
if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
return;
Expand Down
Loading