Add user timing marks for scheduling profiler tool

[taneliang]

Summary

This PR adds User Timing marks at key points in the reconciler's execution. The marks will be used by a new concurrent mode profiler tool that we're building.

High level breakdown:

• Add user timing marks to places where DebugTracing logs.
• Add user timing marks to most other places where the original draft branch marks. We don't mark scheduler started/stop events because those seem to exist for the profiler to know the priority of the marked events. The profiler does not need to know this because 1) the event marks already contain lane information, and 2) the new lane-based concurrent mode scheduling profiler design only displays fiber lanes and not scheduler priorities.
• Tests added to cover all marks

Resolves #5.

Test Plan

• yarn test
• yarn test-prod
• yarn lint
• yarn flow
• Profiled a test app with Firefox Profiler. Marks are visible in output (see sample.
  

Roadmap to completion

• @kartik918 to add the callsites for the remaining 6 marks: mark(Commit|(Layout|Passive)Effects)(Started|Stopped)
• Add back tests for @kartik918's callsites
• Write tests covering markRenderYielded and markPassiveEffects*
• For curiosity: Figure out why @jest-environment node is required for supportsUserTiming to be true when the first test is run (Add user timing marks for scheduling profiler tool #11 (comment))
• Figure out why there are 2 consecutive commit stops in cascading class component updates and cascading layout updates My bad, there are also 2 commit starts, so this makes sense.
• Figure out why there's an Unknown component render being scheduled Edit: I don't think this blocks this PR
• Decide whether to use lane bitmask decimal number or binary. Binary will be human readable (we probably don't care about this though) and it'll also communicate the number of lanes, decimal will be efficient. Update: changed to decimal
• Ensure lint passes
• Ensure flow passes
• Internal code review Skipped
• Merge master once DebugTracing is relanded on master
• Merge master before final PR to React

[taneliang]

@jevakallio These are the steps to repro the bug we discussed on Discord:

1. In packages/shared/ReactFeatureFlags.js, flip enableSchedulingProfiling to true
2. Run yarn test --watch SchedulingProfiling. All tests should pass.
3. .skip the test on line 55 (if you don't do this, after the next step it'll pass and thus fail the @gate check -- probably easier to debug this on another failing test without gate in the way)
4. Delete this @jest-environment node line.
5. The first test should fail as the marks array is empty (instead of being filled with the expected marks). If you .skip it, the next first test will fail.

It may be easier to step through this with a debugger, but the cause is that during the first test that runs, supportsUserTiming defined in packages/react-reconciler/src/SchedulingProfiling.js is false. I'm not sure why this is happening, and I'm not sure if changing the Jest env is the best solution to this.

Our beforeEach code sets a mock global.performance in this file. It appears that it's not getting set before that line is executed in the default Jest env (jsdom?), but it is getting set in the node environment. Also, it looks like SchedulingProfiling.js is getting required after every test in order to re-trigger that check.

This env change was also done in this other test file that also sets global.performance. Maybe this is the correct solution? It'll be cool if we could figure out why 😆

[jevakallio]

I'm able to reproduce the issue. Will look into debugging it tomorrow, but don't hold your breath :)

[jevakallio]

Took a look at this, did not cover the root cause so far.

Things I investigated and ruled out:

• Babel transpilation hoists require calls to the top of module
• require.cache is primed before first test by some other module

Things I haven't looked at yet:

• How jsdom and node module resolution semantics differ. Does jsdom preprocess the file before loading it?
• Ghosts

[taneliang]

@jevakallio Would also appreciate if you could see if this new condition makes sense.

This code marks when a render is cancelled, and the condition replaces an expiration date-based one. I'm not too confident of my understanding of both lanes and expiration times, so this is the best I could come up with.

The marks look like they're in the correct position at least, and I don't see them in unexpected places either.

Update: the screenshots below are outdated: our bitmask is now transmitted in decimal (e.g. --render-start-512)

[bvaughn]

This will detect an interruption, but it will also have false positives.

I believe a way to make it have fewer false positives would be to check that there are actually WIP lanes, e.g.

if (
  workInProgressRoot !== null &&
  workInProgressRootRenderLanes !== NoLanes &&
  !includesSomeLane(workInProgressRootRenderLanes, lane)
) {
  // ...
}

But I think this will also still have false positives during hydration. I'm actually not sure of what to do here. Maybe we should just leave this as a "TODO" entirely and we can discuss it with Andrew on the final PR.

[taneliang]

Oh good catch. Checking for WIP lanes makes sense.

I know this doesn't really affect our profiler tool, but I'd love to understand the lanes architecture better: why would there be false positives during hydration?

[bvaughn]

To be clear, I think we should remove this entirely for now. Even with the wip lanes check, I think this would report renders are being "abandoned" when they weren't. Like I said, I'm actually not sure of what to do here 😄 let's talk more about it on the final PR.

[taneliang]

😄 Yeah sounds good. I've removed markRenderAbandoned and this call in 4101fd7, and we can revert it if we figure out a way to do this. Thank you!

[kartikcho]

Added callsites for the remaining user timing marks

[kartikcho]

Everything looks good to me! Checkout the nit in my comment below.

[taneliang]

Upstream PR is landed! 🎉