DevTools: Profiler: Enable correlating console logs to profiler output (and vice versa)

[justingrant]

A challenge with the React DevTools profiler is that it's too hard to correlate profiler results with console logs. This makes diagnosing and fixing render performance issues much more difficult.

For example, yesterday I was debugging an app where each render usually took 10ms-20ms except every 20-30 renders it'd take 600-800ms. It was frustrating that I didn't have a way to correlate the profiler UI (which told me which renders were problematic) with the verbose console log output that might tell me exactly what went wrong during those renders. Instead I had to comb through logs and guess which output came from "bad" renders. This was tedious and error-prone.

Anyway, my proposal is for React DevTools to make it easy to correlate profiler results with console log output. Both directions would be useful:

1. navigate from logs to profiler - if I see a suspicious line in the logs, I'd like to easily navigate to the profiler with the specific component/commit selected that was running when the line was logged.
2. navigate from profiler to logs - if I see a suspiciously long commit, I'd like to select it in the profiler pane and have an easy way to see associated logs.

I don't have a strong opinion about how this should be accomplished, but below are a few ideas to spur discussion.

A minimal solution could be something like this:
a) The profiler assigns a unique ID to each commit
b) The profiler's right pane would show the ID for each commit
c) React would add a new hook that'd return that ID
d) Userland code could include the ID in logs.

Just this minimal support would be a vast improvement.

If we wanted to make it smoother, here's a few ideas that could be layered on top.

1. Profiler->Console Links The ID in the profiler UI could be a hyperlink that'd open the console drawer and put the ID in the console's CMD+F search box. This would be one-click navigation from profiler to logs. I don't know if Chrome allows this kind of cross-pane control, over the console UI so this might not be practical.

2. Console -> Profiler Links For one-click logging in the other direction., we could have a special URL format (e.g. react://profiler/commit/2c1056b5-1be1-43d4-a105-1d840cf4f9c3) that would enable userland code to emit links in the console that, when clicked, would navigate to the specific commit (in the profile pane) that was active when the logs were emitted. Similar caveat as above: I'm not sure if chrome extensions can be "deeplinked" like this.

3. Log Components Where Building on (1) and (2) above, we could enable console<->profiler linking without requiring changes to userland code. We could have a profiler setting (e.g. "log components where" with UX like "hide components where") that, when active, would emit a line to the console log at the start of each render of a matching component. The output would link back to the profiler, e.g.
   [RDT] Starting MyCoolComponent (react://profiler/commit/2c1056b51be143d4a1051d840cf4f9c3).

What do you think? I'm unfamiliar with React and RDT internals so there might be much better ways to solve log<->profiler correlation than my naive ideas above. But at least I wanted to call out the problem and encourage discussion about a solution.

[markerikson]

Would using the React <Profiler> API help at all here?

https://reactjs.org/docs/profiler.html

[bvaughn]

Have you considered logging with console.warn and using DevTools to auto-append the component stack? If so, what does this approach not provide that you would need? I believe it would identify where in the tree your specific logs were coming from.

[justingrant]

@bvaughn - I know which component is having the problem, but I don't know which one of 100+ renders of that component (it's re-rendered in response to IntersectionObserver callbacks during scrolling, so it renders frequently!) is the problematic one. What's missing is a way to correlate a specific problematic component & commit pair to the logs emitted during that the render(s) and effect(s) that were part of that commit. Ideally, once that basic capability existed, it'd also be easy in the DevTools UI to navigate back and forth between the profiler view (which is the easiest way to identify problematic component/render pairs) to the logs which can provide more detailed diagnostic info about what's happening during a specific render.

@markerikson - I guess I could roll my own poor-man's implementation of what the the RDT profiler does by measuring the render of every component that I suspect of causing the problem and logging the results, but that seems like a pretty heavyweight userland solution. Seems like it could be a lot easier with some small tweaks to RDT. Or do you have some other simpler solution in mind that I'm not thinking of?

[bvaughn]

@justingrant As a way of unblocking yourself, you could fake this using a counter ref that you (a) include in your logs and (b) increment in an effect (to count the number of unique commits), e.g.

const countRef = useRef(0);

useEffect(() => countRef.current++);

console.group(`Commit ${countRef.current}`);
// Logs here...
console.groupEnd();

[justingrant]

@bvaughn - Interesting. What's the best way to identify (in React DevTools Flamegraph) the index of a specific commit of a component that rendered 100+ times? As a one-off I could inspect the HTML to open a "devtools of devtools" instance, and then run some javascript in the Console that would label the commits with an index, e.g.

[...document.getElementsByTagName('button')]
  .filter(b=>b.className.includes('Commit'))
  .forEach((el, i)=>el.innerText = `${i}: ${el.innerText}`)

Is there a simpler way?

[bvaughn]

@bvaughn - Interesting. What's the best way to identify (in React DevTools Flamegraph) the index of a specific commit of a component that rendered 100+ times?

If you select the component, the right hand panel in the profiler will show the number of times it committed- and which one you've currently selected. It isn't optimized for showing 100s of items, in that it doesn't show #1, #2, ...#100 - but it would at least let you identify the index.

[justingrant]

Cool, thanks for the advice. For one-off troubleshooting that will work. Are effects guaranteed to run (before? after?) each commit? Even in StrictMode where every component renders 2x?

[bvaughn]

Are effects guaranteed to run (before? after?) each commit? Even in StrictMode where every component renders 2x?

Yes, after each commit (though not necessarily immediately after) and only once.

[justingrant]

@bvaughn - Hopefully final related question: how does the Flamegraph view account for the double renders in StrictMode DEV mode? Is it the first render, the second render, or both renders that get timed by the RDT profiler and included in the Flamegraph?

[bvaughn]

Profiler and DevTools do not measure the second/strict mode render.

[justingrant]

Profiler and DevTools do not measure the second/strict mode render.

@bvaughn - Looking at the reconciler code, it looks like React throws away the first render in strict mode but uses the second render. Is DevTools really measuring the render that React's not using? Or did you really mean to say that DevTools ignores the first render (the one React ignores too) and only measures the second render? Or am I misinterpreting what the code below is doing?

react/packages/react-reconciler/src/ReactUpdateQueue.js

Lines 275 to 290 in 0cf22a5

	if (typeof payload === 'function') {
	// Updater function
	if (__DEV__) {
	enterDisallowedContextReadInDEV();
	if (
	debugRenderPhaseSideEffectsForStrictMode &&
	workInProgress.mode & StrictMode
	) {
	payload.call(instance, prevState, nextProps);
	}
	}
	const nextState = payload.call(instance, prevState, nextProps);
	if (__DEV__) {
	exitDisallowedContextReadInDEV();
	}
	return nextState;