Add profiling marks to React

[taneliang]

Steps

• Add a enableSchedulingProfiler feature flag.
• Add user timing marks and measures wherever DebugTracing is used. Follow the prototype DataTracing User Timing API calls.
• Add tests similar to the ones for DebugTracing

Unknowns

To Research

• What effect does the reconciler/scheduler priorities actually have? If tasks are executed in the order of priority, where is this ordering/switching happening? Reconciler schedules work using Scheduler.unstable_scheduleCallback, which registers work in a scheduling min heap. The scheduler will thus perform work based on the works' expiration dates, which are computed from the work's priority. There are also other ways to make the scheduler execute something immediately.
• How do the fiber lanes work Lanes bitmask stores the lanes that React is working on. >1 lane can be worked on at any one time, i.e. the lanes are "entangled", meaning that they have a dependency on each other.

Blocked, need Brian

• Is there existing code that generates the user timing stuff? Sounds like there is, since there's test data. Yes. Some of the user timing calls are in facebook/react@master...bvaughn:root-event-marks. Others were in React but removed in Remove Calls to User Timing API facebook/react#18417.

• What priorities are we using? The profiler POC and React's reconciler/scheduler have different priorities. Scheduler priorities, translated to labels in the profiler by priorityLevelToLabel. Fiber lane priorities can be translated to scheduler priorities with lanePriorityToSchedulerPriority.

• Will the new fiber lanes affect the priorities? DebugTracing removed in Temporarily Remove DebugTracing from the New Reconciler facebook/react#18697, with a note saying that "Priority field on update isn't useful anymore since the lanes convey more info". The DebugTracing functions are called with priority either retrieved from getCurrentPriorityLevel or have a priority level passed to it. These can still be used in the fiber lane reconciler. However, log(Force|State)UpdateScheduled functions are called using priority levels retrieved from inferPriorityFromExpirationTime, which has no analog in the lane implementation. Questions:

  • Why can't the log*UpdateScheduled callers also use the priority levels from getCurrentPriorityLevel?
  • If we can't, what should we do? Is there a way to compute a Lane's LanePriority? lanePriorityToSchedulerPriority can then convert them to scheduler priorities.

  We will use lanes instead of priorities.

• In the same PR, "Some of the concepts are changing" -- is there anything else that will affect our profiler? We'll use lanes instead of priorities, so we will display 31 lanes instead of 4 priority rows.

• Should we add the DebugTracing code to the new lane reconciler first, since it's already replaced the old expiration time design in master? Done in Re-enabled DebugTracing feature for old reconciler fork facebook/react#19142

• Brian mentioned in the video that "new React implementation... can have multiple cooperative chunks of work per lane". Is this the new lane reconciler that Andrew is working on? If so, this sounds like we need to record the lanes the work is scheduled on instead of (or together with?) the work's React priority. No, this sounds more like the scheduler package.

• Eng culture: would the React team prefer us to split this into a stack of individual PRs like FB's internal Diffs, or would you rather us implement a complete feature in one PR? Seems like the latter is preferred based on past React PRs, but I wanted to make sure.

• Nonblocker, but for understanding: Brian mentioned in the onboarding video that the unscheduled priority lane has things that were "scheduled outside of the scheduler API". How does that happen in a React app?

Acceptance criteria

1. If enableSchedulingProfiler is true:
   1. User event marks should be generated, following facebook/react@master...bvaughn:root-event-marks (ignoring renderAbandoned as DebugTracing does not have that).
2. Else no change to existing behavior.

Tests should be written.

References

• Project description https://github.com/MLH-Fellowship/0.4.x-projects/wiki/React-Concurrent-Mode-Profiler
• DebugTracing logger PR Add experimental DebugTracing logger for internal use facebook/react#18531
• DebugTracing prototype facebook/react@master...bvaughn:root-event-marks
• Updated DebugTracing for "lanes" PR Re-enabled DebugTracing feature for old reconciler fork facebook/react#19142

[jevakallio]

@bvaughn, input needed on above when you've got a minute or 60 ☝️😃

[bvaughn]

@taneliang We should chat for a bit. Hopefully @jevakallio can coordinate something?

I don't think I agree with some of the steps (1-3, 5). This new profiling data is not something that we are planning to expose via a programmatic API (like React.Profiler). It's something that will feed into the React DevTools extension eventually (and for now, a separate, standalone profiling tool like the prototype I shared from a few months ago).

So a feature flag like enableSchedulingProfiler is a good step, but REACT_SCHEDULING_PROFILER_TYPE and unstable_SchedulingProfiler and mode changes aren't required.

Should we add the DebugTracing code to the new lane reconciler first, since it's already replaced the old expiration time design in master?

The DebugTracing stuff needs to be added back in since Seb removed it temporarily then Andrew overrode the old reconciler with the new one. I'll try to get this done sometime this week if possible... I have a lot of catchup to do because I was out all last week. This is probably something I should own though.

In the same PR, "Some of the concepts are changing" -- is there anything else that will affect our profiler?

Possibly. I need to talk with Andrew/Seb about their thinking a little here to find out more. I'll report back as soon as I've got a better mental image of this. General concept is likely still the same, but the profiler UI might be a bit different.

would the React team prefer us to split this into a stack of individual PRs like FB's internal Diffs

I think a single PR makes sense for now. We can always talk about splitting up if it looks like it's too big to review.

Brian mentioned in the onboarding video that the unscheduled priority lane has things that were "scheduled outside of the scheduler API". How does that happen in a React app?

The idea was that JavaScript that wasn't scheduled (through the scheduler API) was essentially always highest priority (because the scheduler API couldn't prioritize it to allow other things to come before it).

I'm not sure how relevant that comment of mine was for the new lanes architecture though. Let me get back with info about this too. Sorry!

[taneliang]

Thanks @bvaughn! Also saw your comments on MLH-Fellowship/scheduling-profiler-prototype#1

mode changes aren't required

Ah. In that case, should we only produce the user timing marks when the feature flag is true and, for updates/suspends, the fiber has ProfileMode? I'm thinking the ProfileMode check should be there so that we don't unnecessarily add a lot of overhead (as mentioned in facebook#18417). Since this mode is automatically set when React DevTools is present, this would also cover our profiler's eventual integration with React DevTools too.

This is probably something I should own though.

Understood! Though, I'd be happy to do it if you'd like me to -- it may be a good onboarding task for me as I think it'll help me understand React better.

General concept is likely still the same, but the profiler UI might be a bit different

Looking forward to hearing more about this tonight :)

I think a single PR makes sense for now

👍

The idea was that JavaScript that wasn't scheduled (through the scheduler API) was essentially always highest priority (because the scheduler API couldn't prioritize it to allow other things to come before it).

I think this makes sense. Thanks!

[bvaughn]

In that case, should we only produce the user timing marks when the feature flag is true and, for updates/suspends, the fiber has ProfileMode?

No. We should only look to the feature flag for now- this has nothing to do with a mode, since there is no programmatic API for collecting this new data (yet) and React DevTools isn't really even involved (at least for now).

The User Timing API overhead mentioned in facebook#18417 was due to the performance.measure calls, which we are not using here (only performance.mark). I believe Chrome also recently fixed a performance issue (unclear of how much this helped since we haven't benchmarked it) with performance.measure where they were previously cloning values unnecessarily.

Understood! Though, I'd be happy to do it if you'd like me to -- it may be a good onboarding task for me as I think it'll help me understand React better.

Okay, we can talk about it today then during our meeting.

[bvaughn]

By the way, the debug tracing feature is back in master (in the old reconciler fork) so hopefully the user timing marks work should be unblocked now. Please let me know if there are questions about the differences between the lanes impl and the old expiration time/priority impl. I think the lanes stuff is a bit easier for us, FWIW! 😄

[taneliang]

Yeah! I saw the PR and I've started working on the user timing marks. Got a few more questions if you don't mind:

1. I noticed that in your original root-event-marks branch you had TODOs to "Generate and store temporary ID so DevTools can match up a component stack later", and that there's a getWakeableID function in DebugTracing that seems to do this. What does it mean to match up a component stack? Trying to understand if we should add these wakeable IDs into the new scheduling profiler stuff as well and what they can be used for.

2. I noticed that there are some differences between your draft branch and DebugTracing:

   1. Draft branch logs --render-cancel and --schedule-render.
   2. DebugTracing logs wakeable resolves/rejects and force updates.
   3. The draft distinguishes between render stops and yields, but (if I remember correctly) DebugTracing just logs them both as stops (and from what I can tell, we are still able to differentiate stops and yields as the draft method's callsites' callsites are still present).

   Should we follow the events in DebugTracing or the events in the draft branch?

   The profiler POC used events from your branch so those may be the ones we're interested in, but as the final DebugTracing came a while after your draft I'm not sure if the team has decided on a different set of interesting events.

3. Code style: we'll be duplicating DebugTracing's formatLanes and possibly getWakeableID as well. Is there any place you'd suggest we refactor them to, or should we put the marks in the DebugTracing file since they're sort of related?

[bvaughn]

1. This TODO can still be ignored for now. The idea is that the profiling tool should eventually show component stacks in the tooltip in addition to the component name, but this requires two things: (1) capturing the stack (slightly costly) and (2) serializing the stack (since the current profiler tool is a totally separate app). I'm not sure either of those is worth the effort right now.

2. For the profiling tool, we should log the more detailed version in all cases. e.g. debug tracing initially logged e.g. render scheduled but it wasn't useful for how that tool is used.

3. Duplicate (fork) functions like formatLanes and put it all in a new file 😄

[taneliang]

The idea is that the profiling tool should eventually show component stacks in the tooltip in addition to the component name... I'm not sure either of those is worth the effort right now.

I see. I think the branch did serialize the component stack and the tool does parse it. Should I remove this from both React's marks and the tool then?

we should log the more detailed version in all cases

Cool, that makes sense. We'll mark whatever the draft branch marked ∪ whatever DebugTracing logs :)

Duplicate (fork) functions like formatLanes and put it all in a new file

Sounds good!

[bvaughn]

I see. I think the branch did serialize the component stack and the tool does parse it. Should I remove this from both React's marks and the tool then?

Oh, I'd forgotten that I'd added that I guess.

Short answer: Don't care too much now. Should be easy to add (or remove) later.

The TODO is still not relevant since it mentions storing an ID for DevTools to retrieve later (to reduce the serialization overhead) but that assumes DevTools is running with access to the shared memory. In this case, since the new Profiler is a separate app, that TODO doesn't apply.

[bvaughn]

Since we are actively changing the "lanes" implementation and what the semantic value of a given lane is (e.g. facebook#19287) it would be helpful for us to encode some info in our profile that lets us match this information up later.

I had been thinking about eventually encoding what the lanes ranges are, so we could display some meaningful label in the profiler, but maybe that would be a hassle and for now- we could get away with just marking the version of React the profiling data corresponds to. This would let us at least manually match the lanes up later if we wanted to dig in deeper.

[taneliang]

Makes sense! I'll add React version numbers to all the marks as I can't find a way to detect the start of a profile.

Will using that version number of React be useful for FB's profiling data given that www is on bleeding edge versions, or is this more for users of the tool outside FB?

[bvaughn]

I don't think we need to do that. That would bloat to the data unnecessarily 😄 Let's just add it to one of the low frequency marks, like render-scheduled?

FB gets a version that's based on the git commit it was built from (e.g. "16.13.1-766af5968") so it will be fine for us too.

[bvaughn]

I can't find a way to detect the start of a profile.

This would be something we could do later, once we have tighter integration with DevTools.

[taneliang]

Ah yes, adding it to a low frequency mark makes more sense 😆 I don't think render-scheduled gets called after the initial page load, so I'll add it to commit-start instead?

[bvaughn]

Hm. I guess that's a reasonable point. Render scheduled isn't called often. Generally only on page load. So I guess logging it there isn't much better than logging it on its own during module-init. Hm... that kind of sucks. We commit fairly often too and it's a little irksome to have an extra bit of data just floating along there.

Maybe let's file a follow up issue for this and give it a little more thought first.

[acdlite]

I had been thinking about eventually encoding what the lanes ranges are, so we could display some meaningful label in the profiler

Another possibility is to add an API to the DevTools hook that allows the profiler to ask the renderer what the priority is for a given task identifier. That way the profiler isn't coupled to any particular implementation.

[bvaughn]

Once we get this integrated with the DevTools, that could work! I think that integration is going to be a good bit of work though.

At that point, we would not need to mark the React version either, because DevTools already knows it.

The one case these both fall down on is if there are multiple React (versions) on a page. Maybe we just wouldn't support that case for this profiler?

[acdlite]

Oh right I see, I forgot this profiler is separate from DevTools. Also even once it’s integrated you would want to encode this in the serialized log so that the data can be read back later.

For stuff about the renderer that never changes, could you log that stuff once at the beginning of the profile?

[bvaughn]

Also even once it’s integrated you would want to encode this in the serialized log so that the data can be read back later.

Yes, but DevTools would likely pre-process the data before exporting it, like it does with the current profiling data. So it could add metadata about the React version, lanes, etc.

[bvaughn]

For stuff about the renderer that never changes, could you log that stuff once at the beginning of the profile?

Yes, once DevTools is the thing that starts profiling. But right now you start/stop profiling with Chrome's performance tab and there's no event to listen to saying "profiling has just started" - so the only thing we could do would be to log it once at startup, during module init (as discussed above) but this only works for the reload-and-profile use case, not for a use case of doing some things and then starting profiling in the middle (which is pretty common)

[bvaughn]

Looks like this all got finished, so I'm going to close this out.