[Performance] [Audit] `withOnyx(ReportActionCompose)` is very slow to render

If you haven’t already, check out our contributing guidelines for onboarding and email contributors@expensify.com to request to join our Slack channel!

This report is part of #3957, scenario "Rendering Individual chat messages".

Commit log

The full commit log can be inspected with Flipper or React Devtools, see https://github.com/Expensify/Expensify.cash/issues/3957#issuecomment-881045715 for instructions. This excerpt takes commits relevant to one withOnyx(ReportActionCompose) instance, child of cell with key 70797025.

SHOW LOG

Renders withOnyx(ReportActionCompose), first render

Renders withOnyx(ReportActionCompose), because betas state changed

Renders withOnyx(ReportActionCompose), because comment state changed

Renders withOnyx(ReportActionCompose), because modal state changed

Renders withOnyx(ReportActionCompose), because network state changed

Renders withOnyx(ReportActionCompose), because myPersonalDetails state changed

Renders withOnyx(ReportActionCompose), because personalDetails state changed

Renders withOnyx(ReportActionCompose), because reportActions state changed

Renders withOnyx(ReportActionCompose), because report state changed

192

Renders withOnyx(ReportActionCompose), because blockedFromConcierge state changed

193

Renders withOnyx(ReportActionCompose), because loading state changed

215

Renders withOnyx(ReportActionCompose), because reportActions state changed

220

Renders withOnyx(ReportActionCompose), because report state changed

Flamegraph

Problems

First of all, the commit log already highlights issue reported in #4101, but there is more. Inspect the log by pressing SHOW LOG in the section above.

Issue 1: `loaded` state is set to true very lately (c220, at 6.1s)

It looks like blockedFromConcierge is fired lately (c192, at 5.4s) while the latest preceding value was fired in c76 (at 1.7s), so that's over 3 seconds later.

Issue 2: `report` and `reportActions` are emitted multiple times

report is emitted at c31, c76 and c220
reportActions is emitted at c30 and c215

Proposal: investigate further those Onyx bottlenecks

Assess why blockedFromConcierge is fired 3.7 seconds after the first burst ending at c31
Assess why report and reportActions are emitted multiple times for the same cell

Triggered auto assignment to @michaelhaxhiu (AutoAssignerTriage), see https://stackoverflow.com/c/expensify/questions/4749 for more details.

I'm not sure, but if I had to guess I'd maybe think the late "loaded" is in part possibly to the fact that we are fetching this data cold from storage instead of using any cache. I think @kidroca's cache improvements might be addressing some part of this. We have caching but we somewhat aggressively clear this cache at the moment. Adding LRU caching will probably help here since we subsequent reads will be faster - although initial reads would still be as slow as they are now.

Issue 2: report and reportActions are emitted multiple times

reportActions are fetched when we navigate to a report so I would expect that we'd see this connected prop update several times:

Once when we connect and anything in storage would be returned
Again when we update the key with the result of the API call

The report key changing could be because we are storing some information on the report object. Things like when it was last accessed are stored there and also updated when we navigate to it (which would trigger a re-render). Or said another way, the event of navigating to a report will trigger a render:

Once when the report data is grabbed from storage
Another when the view itself triggers a modification of that data

Hard to say whether that is a problem or not, but that might help guide someone to look into this further.

Also maybe it's just as simple as... ReportActionCompose doesn't really need all the information we are passing to it. There are a boatload of subscribers...

https://github.com/Expensify/Expensify.cash/blob/fc965f68d308167d19d00a29b91e85ca33707882/src/pages/home/report/ReportActionCompose.js#L648-L677

Are we really using all the information being passed to it?

I suggest we break it down into sub-components.

@marcaaron

reportActions are fetched when we navigate to a report so I would expect that we'd see this connected prop update several times

The thing is, we're only interested in one peculiar report action in this component. There is a high chance that the report action didn't change after being fetched, but the reference in memory will have changed, causing a re-render. Is there a history version ID for each report action (or last modified field) that you could use in order to avoid extraneous commits, by using shouldComponentUpdate or React.memo? That logic could otherwise be handled in Onyx to avoid re-emitting report actions that haven't changed.

Hey guys I think I know why this view is slow to render and it is this composition right here

https://github.com/Expensify/Expensify.cash/blob/429e7bb7e4cd6bcb945375102c780ee9b600c7f2/src/pages/home/report/ReportActionCompose.js#L445-L458

This composition is evaluated at render time, before adding the spinner you could even see the compose box coming together in chunks

A quick test can be to remove the AtthacmentModal and picker and just render the TextInputFocusable - I did it a long time ago (before emojis and the other items added there) and it rendered instantly

There is a high chance that the report action didn't change after being fetched, but the reference in memory will have changed, causing a re-render. Is there a history version ID for each report action (or last modified field) that you could use in order to avoid extraneous commits, by using shouldComponentUpdate or React.memo?

Perhaps... if we are trying to eliminate the reportActions subscription then we can try to move this logic elsewhere and maintain a reference to the reportActions without triggering any re-renders?

https://github.com/Expensify/Expensify.cash/blob/fc965f68d308167d19d00a29b91e85ca33707882/src/pages/home/report/ReportActionCompose.js#L309-L317

It seems there is no reason this component needs to be constantly aware of reportActions changing since we only need to know the current state when the "up" key is pressed.

To be honest, there are lots of small issues like this everywhere that make app logic unnecessarily complicated and add more subscribers than necessary. This could quite easily be solved by having a store getter. e.g. if instead of a subscription this was replaced with a synchronous call to retrieve the cached value of reportActions.

A quick test can be to remove the AtthacmentModal and picker and just render the TextInputFocusable - I did it a long time ago (before emojis and the other items added there) and it rendered instantly

That's also interesting @kidroca I wonder if the two issues are somehow compounded. Bad rendering performance of the AttachmentModal combined with unnecessary renders sound like a double whammy for ReportActionCompose.

I maybe want to suggest holding on solving this one in particular, but curious if others agree. In my own testing, this component doesn't seem to have a great impact on chat switching times. I removed it completely from the code and the slowness related to switching from one chat to another was still present.

Which tells me that the highest value improvements will be to improving rendering speed of individual report actions.

@marcaaron I just want to emit one hypothesis though: if other elements in the render tree of each cell suffer from the same lag (e.g. some subscribed values are emitted very lately), then your testing would have missed its target. Perhaps it would be interesting, although a substantial endeavor, to render a list from hard-coded data (with the same HTML content to render) in order to efficiently assess the alleged lag caused by Onyx.

if other elements in the render tree of each cell suffer from the same lag (e.g. some subscribed values are emitted very lately), then your testing would have missed its target

Ah, let me see, so in this case, ReportActionCompose there is only one per chat. My naive assumption is that by removing it entirely (all other things being equal) the chat screen should render faster. But it does not have a noticeable impact (this is w/out any benchmarks and me just using my eyes).

Am I correct in understanding that Peter's PR adds a repeatable benchmark timing code? Can you test it using that?

On Mon, Jul 19, 2021, 4:15 PM Marc Glasser @.***> wrote:

if other elements in the render tree of each cell suffer from the same lag (e.g. some subscribed values are emitted very lately), then your testing would have missed its target

Ah, let me see, so in this case, ReportActionCompose there is only one per chat. My naive assumption is that by removing it entirely (all other things being equal) the chat screen should render faster. But it does not have a noticeable impact (this is w/out any benchmarks and me just using my eyes).

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/Expensify/Expensify.cash/issues/4116#issuecomment-882922497, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAEMNURWZ6B2FDKV3HHJSGDTYSWYZANCNFSM5AP6IQDQ .

So far we've seen it used to more broadly show the total time Onyx spent working.

@kidroca Is there a way we can use your tool to granular and maybe see how much time a single component and all its children spent communicating with Onyx?

If not, one idea for how to do it would be

start a timer when withOnyx() mounts
end it when all data is available and the wrapped component renders

That should tell us how long the wrapped component was "waiting for data"

On the other hand, to get a rough idea for how much time a component spent laying out it's UI we can

start a timer when the wrapped component mounts
end it when an onLayout callback is triggered for the UI item we are measuring inside the wrapped component

It would be good to differentiate between how long something is "waiting for data" from how long something "takes to show up on screen" after it has all the data it needs.

Quick update on that idea above... I tried hooking up a basic start/end trace to withOnyx to get some timing information for how much "waiting" we are actually doing. It seems like there is a cascading effect where components are waiting for the data from Onyx, but also waiting for each other to get that data first. I'm not 100% sure this is happening but this data seems to suggest it is since there are cases where each message is taking an incrementally larger amount of time to render nearly identical data.

[Onyx] withOnyx(ReportView) loaded in: 100.10 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 105.10 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 114.80 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 121.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 129.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 134.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 142.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 147.80 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 155.90 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 185.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 187.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 195.80 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 198.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 200.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 208.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 209.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 210.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 217.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 215.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 218.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 226.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 224.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 227.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 235.50 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 237.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 241.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 246.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 246.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 249.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 256.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 254.20 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 256.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 264.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 264.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 266.20 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 273.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 273.90 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 276.50 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 282.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 280.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 282.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 289.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 287.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 289.50 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 295.80 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 294.50 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 296.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 302.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 301.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 303.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 311.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 308.20 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 310.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 317.20 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 312.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 314.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 321.80 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 316.50 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 318.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 324.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 322.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 324.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 329.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 321.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 322.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 329.80 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 323.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 326.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 333.50 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 329.60 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 331.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 337.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 334.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 336.80 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 341.90 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 337.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 341.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 347.90 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 344.20 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 346.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 352.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 347.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 349.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 354.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 513.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 512.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 511.10 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 507.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 504.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 503.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 502.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 499.80 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 498.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 497.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 494.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 492.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 490.90 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 489.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 484.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 480.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 474.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 470.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 462.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 455.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 450.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 446.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 442.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 440.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 434.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionCompose) loaded in: 689.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 148.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 146.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 143.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 140.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 140.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 137.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 134.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 133.10 ms
2withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 132.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 101.40 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 102.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 104.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 110.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 110.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 112.10 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 119.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 176.90 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 174.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 172.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 169.90 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 167.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 165.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 160.80 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 158.80 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 156.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 154.90 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 104.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 156.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 154.90 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 152.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 150.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 148.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 146.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 145.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 141.90 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 139.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 139.30 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 106.10 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 160.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 157.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 155.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 154.90 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 151.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 150.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 146.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 144.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 142.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 141.20 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 100.70 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 100.50 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 103.00 ms
withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 108.90 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 159.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 158.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 157.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 153.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 152.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 151.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 148.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 147.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 145.40 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 143.90 ms

Whoa. So what does that mean, and how do we fix it?

On Mon, Jul 19, 2021, 10:35 PM Marc Glasser @.***> wrote:

Quick update on that idea above... I tried hooking up a basic start/end trace to withOnyx to get some timing information for how much "waiting" we are actually doing. It seems like there is a cascading effect where components are waiting for the data from Onyx, but also waiting for each other to get that data first. I'm not 100% sure this is happening but this data seems to suggest it is since there are cases where each message is taking an incrementally larger amount of time to render nearly identical data.

[Onyx] withOnyx(ReportView) loaded in: 100.10 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 105.10 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 114.80 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 121.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 129.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 134.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 142.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 147.80 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItem) loaded in: 155.90 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 185.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 187.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 195.80 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 198.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 200.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 208.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 209.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 210.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 217.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 215.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 218.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 226.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 224.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 227.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 235.50 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 237.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 241.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 246.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 246.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 249.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 256.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 254.20 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 256.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 264.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 264.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 266.20 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 273.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 273.90 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 276.50 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 282.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 280.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 282.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 289.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 287.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 289.50 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 295.80 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 294.50 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 296.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 302.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 301.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 303.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 311.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 308.20 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 310.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 317.20 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 312.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 314.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 321.80 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 316.50 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 318.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 324.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 322.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 324.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 329.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 321.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 322.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 329.80 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 323.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 326.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 333.50 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 329.60 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 331.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 337.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 334.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 336.80 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 341.90 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 337.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 341.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 347.90 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 344.20 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 346.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 352.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 347.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 349.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 354.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 513.50 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 512.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 511.10 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 507.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 504.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 503.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 502.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 499.80 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 498.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 497.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 494.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 492.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 490.90 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 489.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 484.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 480.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 474.50 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 470.20 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 462.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 455.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 450.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 446.50 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 442.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 440.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 434.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionCompose) loaded in: 689.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 148.20 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 146.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 143.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 140.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 140.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 137.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 134.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 133.10 ms 2withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 132.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 101.40 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 102.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 104.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 110.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 110.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 112.10 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 119.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 176.90 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 174.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 172.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 169.90 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 167.50 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 165.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 160.80 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 158.80 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 156.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 154.90 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 104.50 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 156.20 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 154.90 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 152.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 150.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 148.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 146.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 145.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 141.90 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 139.60 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 139.30 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 106.10 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 160.00 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 157.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 155.20 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 154.90 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 151.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 150.20 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 146.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 144.50 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 142.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 141.20 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 100.70 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 100.50 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 103.00 ms withOnyx.js:123 [Onyx] withOnyx(WithLocalize(ConfirmModal)) loaded in: 108.90 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 159.20 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 158.70 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 157.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 153.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 152.50 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 151.20 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 148.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 147.30 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 145.40 ms withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 143.90 ms

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/Expensify/App/issues/4116#issuecomment-883074819, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAEMNUTBB33VOAFRUQAWEDLTYUDJ3ANCNFSM5AP6IQDQ .

@kidroca Is there a way we can use your tool to granular and maybe see how much time a single component and all its children spent communicating with Onyx?

It only works for promise based functions, and help us track how much time we spent reading/writing individual keys. It's not suitable to measure render, but the print/export functionality developed there can help

Instead of patching Component code with start/end I found this: import { Profiler } from 'react' This Profile component can be used to wrap whatever part of the app needs measuring: https://reactjs.org/docs/profiler.html It will capture timing information

So we can do something like this:

Onyx.js

        withOnyx.displayName = `withOnyx(${getDisplayName(WrappedComponent)})`;
        return React.forwardRef((props, ref) => {
            const Component = withOnyx;

            return (
               // This is turned off in production and just returns the child Component
              <Profiler id={props.profileId || Component.displayName} onRender={reactProfilerCallback}>
                  <Component {...props} forwardedRef={ref} />
              </Profiler>
            );
        });

As a POC I've implemented reactProfilerCallback in decorateWithMetrics and the result is something like this:

Onyx Benchmark

Android Emulator (DEV=true)
App Init
Last call finished at: 23.74sec
Everything in excel: https://docs.google.com/spreadsheets/d/1O7bOwd6ijB4JTGTphQDtBbE3QPO2Sc_2NdifTuKN69o/edit?usp=sharing

method	total time spent	max	min	avg	time last call completed	calls made
withOnyx(Component)	8.9min	1.12sec	13.363ms	273.036ms	23.74sec	1956
Onyx:get	2.0min	5.84sec	0.069ms	862.688ms	23.40sec	142
withOnyx(ReportActionItem)	1.6min	1.07sec	16.537ms	307.403ms	23.63sec	311
withOnyx(ReportActionItemSingle)	1.4min	1.06sec	27.638ms	396.065ms	23.57sec	207
withOnyx(ReportActionItemMessage)	1.2min	1.05sec	25.139ms	390.623ms	23.57sec	189
Onyx:set	43.71sec	5.82sec	189.819ms	1.90sec	23.15sec	23
Onyx:merge	35.84sec	5.82sec	104.598ms	1.71sec	23.15sec	21
withOnyx(Expensify)	18.70sec	1.17sec	3.681ms	144.976ms	23.74sec	129
withOnyx(AuthScreens)	18.33sec	1.15sec	3.728ms	146.636ms	23.74sec	125
withOnyx(MainDrawerNavigator)	17.43sec	1.13sec	17.663ms	145.269ms	23.74sec	120
withOnyx(ReportView)	14.66sec	1.09sec	15.471ms	133.310ms	23.74sec	110
withOnyx(ReportActionsView)	14.02sec	1.09sec	14.360ms	137.441ms	23.74sec	102
Onyx:mergeCollection	13.54sec	3.10sec	1.93sec	2.71sec	23.15sec	5
withOnyx(HeaderView)	12.58sec	1.12sec	21.250ms	279.454ms	23.40sec	45
withOnyx(SidebarScreen)	2.37sec	293.552ms	14.563ms	44.752ms	23.40sec	53
Onyx:getAllKeys	2.28sec	1.39sec	0.274ms	227.914ms	21.48sec	10
withOnyx(SidebarLinks)	2.25sec	292.080ms	12.977ms	43.184ms	23.40sec	52
withOnyx(ReportActionCompose)	1.50sec	143.967ms	15.809ms	79.104ms	22.93sec	19
withOnyx(IOUBadge)	761.481ms	99.987ms	25.281ms	42.304ms	22.93sec	18
withOnyx(ReportTypingIndicator)	554.185ms	109.307ms	18.599ms	92.364ms	22.93sec	6
Onyx:defaults	234.716ms	234.716ms	234.716ms	234.716ms	883.900ms	1

withOnyx(ReportActionCompose)

This component is on the faster end of `withOnyx` components	start time	commit time	duration (start time - commit time)
2.67sec	2.69sec	15.809ms	phase: mount, actual: 1.159ms, base: 1.008ms
2.78sec	2.80sec	25.281ms	phase: update, actual: 0.508ms, base: 0.560ms
8.32sec	8.36sec	45.281ms	phase: update, actual: 0.735ms, base: 0.785ms
8.39sec	8.42sec	20.990ms	phase: update, actual: 1.173ms, base: 1.123ms
8.44sec	8.51sec	77.899ms	phase: update, actual: 55.480ms, base: 42.320ms
10.23sec	10.32sec	80.136ms	phase: update, actual: 26.434ms, base: 30.331ms
10.34sec	10.39sec	51.456ms	phase: update, actual: 30.990ms, base: 34.514ms
10.77sec	10.85sec	73.497ms	phase: update, actual: 27.651ms, base: 31.520ms
10.87sec	10.94sec	72.445ms	phase: update, actual: 25.917ms, base: 29.831ms
12.14sec	12.28sec	143.617ms	phase: update, actual: 30.242ms, base: 31.206ms
13.29sec	13.43sec	143.085ms	phase: update, actual: 31.842ms, base: 32.784ms
13.55sec	13.60sec	48.256ms	phase: update, actual: 28.976ms, base: 31.666ms
13.66sec	13.73sec	77.402ms	phase: update, actual: 25.898ms, base: 28.532ms
14.06sec	14.11sec	47.590ms	phase: update, actual: 22.909ms, base: 33.291ms
16.05sec	16.12sec	76.784ms	phase: update, actual: 30.294ms, base: 32.876ms
18.20sec	18.34sec	142.257ms	phase: update, actual: 29.936ms, base: 30.591ms
19.72sec	19.86sec	143.967ms	phase: update, actual: 29.838ms, base: 30.307ms
21.39sec	21.47sec	78.888ms	phase: update, actual: 28.008ms, base: 30.570ms
22.79sec	22.93sec	138.340ms	phase: update, actual: 30.053ms, base: 30.988ms

The docs state that actual time is the render time, but as you can see there's a lot more time between start and commit - the commit phase is when React applies any changes, so perhaps the actual update on screen is, let's say, 26ms while the deriving and committing this change took 74ms I'm not certain about the above theory, but I think this gives us enough information to dig deeper, so perhaps my next PR should be integrating this with a dedicated table template for React?

Another cool feature about this is I can set a breakpoint for components that took more than 100 200, 300ms to render and investigate live

It seems like there is a cascading effect where components are waiting for the data from Onyx, but also waiting for each other to get that data first

I'm not sure what are you observing

you see the data getting logged monotonically - waits for an item to render and then renders another?
- if the items are chat messages this comes from the current FlatList configuration maxToRenderPerBatch={1}. I've observed this effect, where an initial count if items render and then +1 item gets rendered each 0.5-1s. This is actually costing more CPU time as noted here: #2629
you see 10 items started at 10 different times but render at the same time?

This is how React works by design, it would batch some updates together for performance. You can see it in my data as well, where several renders of the same component type would have a different start time, but the same commit time (commit is when didMount is called)

commitTime: number - Timestamp when React committed the current update. This value is shared between all profilers in a commit, enabling them to be grouped if desirable.

withOnyx(ReportActionItem)

start time	commit time	duration	args
2.65sec	2.82sec	170.894ms	phase: mount, actual: 8.775ms, base: 8.541ms
2.66sec	2.82sec	154.886ms	phase: mount, actual: 0.913ms, base: 0.823ms
2.67sec	2.82sec	147.006ms	phase: mount, actual: 2.600ms, base: 2.301ms
2.68sec	2.82sec	137.101ms	phase: mount, actual: 1.019ms, base: 0.895ms
2.69sec	2.82sec	129.768ms	phase: mount, actual: 0.913ms, base: 0.820ms
2.70sec	2.82sec	120.504ms	phase: mount, actual: 0.747ms, base: 0.663ms
2.70sec	2.82sec	114.952ms	phase: mount, actual: 1.194ms, base: 1.089ms
2.71sec	2.82sec	107.075ms	phase: mount, actual: 1.046ms, base: 0.941ms
2.72sec	2.82sec	98.420ms	phase: mount, actual: 1.508ms, base: 1.412ms
2.73sec	2.82sec	89.742ms	phase: mount, actual: 1.024ms, base: 0.935ms
2.74sec	2.82sec	81.028ms	phase: mount, actual: 1.127ms, base: 1.024ms
2.75sec	2.82sec	72.329ms	phase: mount, actual: 0.939ms, base: 0.829ms
2.75sec	2.82sec	65.671ms	phase: mount, actual: 0.795ms, base: 0.713ms
2.76sec	2.82sec	59.479ms	phase: mount, actual: 0.799ms, base: 0.717ms
2.76sec	2.82sec	54.896ms	phase: mount, actual: 0.845ms, base: 0.762ms
2.77sec	2.82sec	49.756ms	phase: mount, actual: 0.982ms, base: 0.892ms
2.77sec	2.82sec	45.002ms	phase: mount, actual: 0.540ms, base: 0.449ms
2.78sec	2.82sec	39.541ms	phase: mount, actual: 0.559ms, base: 0.478ms
2.79sec	2.82sec	32.731ms	phase: mount, actual: 0.662ms, base: 0.578ms
2.79sec	2.82sec	27.809ms	phase: mount, actual: 0.789ms, base: 0.669ms
3.38sec	3.56sec	175.463ms	phase: update, actual: 107.386ms, base: 83.738ms
3.62sec	3.79sec	170.863ms	phase: update, actual: 17.418ms, base: 56.918ms
3.66sec	3.79sec	138.213ms	phase: update, actual: 69.823ms, base: 45.505ms
3.86sec	4.10sec	238.384ms	phase: update, actual: 19.771ms, base: 45.477ms
3.90sec	4.10sec	200.964ms	phase: update, actual: 133.709ms, base: 109.000ms

Another reason for such delay is the optimization we have for retrieving value from storage

withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 513.50 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 512.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 511.10 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 507.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 504.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 503.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 502.30 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 499.80 ms
...
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 148.20 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 146.60 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 143.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 140.70 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 140.00 ms
withOnyx.js:123 [Onyx] withOnyx(ReportActionItemMessage) loaded in: 137.00 ms

If the components above all need something that's not in cache - the first component that needs it starts a read from storage, any other components needing the same value would just hook to that call and wait otherwise they will make their own request to read it in parallel and just make it worse for everyone The component that rendered for 137ms probably started mounting about 400ms later than the first one and so it waits the least amount of time. Keeping more items in cache should help with this

Also it's very likely you're printing live on the console withOnyx.js:123 which slows things considerably if it happens for every withOnyx component (2000+ renders during init)

Whoa. So what does that mean, and how do we fix it?

@quinthar In the simplest terms, I think connecting any component via withOnyx() adds a significant delay to the child component's rendering (whether the values it needs are cached or not). So, it would be wise to not have our individual list items subscribed to Onyx. Or come up with another way to share Onyx data with them.

As a POC I've implemented reactProfilerCallback in decorateWithMetrics and the result is something like this:

@kidroca Just to clarify, if we are using the profiler to measure the onRender of withOnyx does this tell us anything about how long withOnyx() took to gather the data before rendering it's wrapped component?

This is how React works by design, it would batch some updates together for performance. several renders of the same component type would have a different start time but the same commit time (commit is when didMount is called)

Can you explain where this batching is happening and how the data collected (either mine or yours) supports it? Not sure I am following, but would be interested in hearing the expert explanation.

I would like to propose that we add some kind of logging to withOnyx() that logs out which component has mounted and how much time it spent gathering data from Onyx. I think this will help us:

identify areas where we can remove those subscribers entirely
think about whether we need to share the data another way

Thoughts on whether this would be valuable / the best way to implement it?

Another reason for such delay is the optimization we have for retrieving value from storage

@kidroca we might be cherry picking information that supports some theories we each want to believe 😅

Yes, there are examples where it becomes incrementally faster for each subsequent component. But also look at this burst of ReportActionContextMenu and you'll see each one takes slightly longer than the next. Any ideas why?

withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 185.60 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 187.60 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 195.80 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 198.10 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 200.40 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 208.70 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 209.30 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 210.70 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 217.40 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 215.60 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 218.70 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 226.00 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 224.30 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 227.70 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 235.50 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 237.60 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 241.00 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 246.70 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 246.70 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 249.30 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 256.40 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 254.20 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 256.40 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 264.10 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 264.10 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 266.20 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 273.00 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 273.90 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 276.50 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 282.00 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 280.00 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 282.40 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 289.10 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 287.70 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 289.50 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 295.80 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 294.50 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 296.60 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 302.10 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 301.10 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 303.70 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 311.70 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 308.20 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 310.30 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 317.20 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 312.70 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 314.40 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 321.80 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 316.50 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 318.40 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 324.60 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 322.30 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 324.00 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 329.10 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 321.00 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 322.70 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 329.80 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 323.60 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 326.70 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 333.50 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 329.60 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 331.30 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 337.00 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 334.30 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 336.80 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 341.90 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 337.40 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 341.30 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 347.90 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 344.20 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 346.30 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 352.40 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 347.40 ms
withOnyx(WithLocalize(ReportActionContextMenu)) loaded in: 349.30 ms
withOnyx(WithLocalize(ConfirmModal))            loaded in: 354.30 ms

Anyways I'm not sure what it all means haha I thought it was interesting or someone might have a better explanation.

@marcaaron With just the duration it's hard to tell, perhaps it's not just the next ReportActionContextMenu rendering, what if all the previous items are forced to re-render for some reason?

If not, one idea for how to do it would be

start a timer when withOnyx() mounts

end it when all data is available and the wrapped component renders

What's the exact implementation for this?

@kidroca Just to clarify, if we are using the profiler to measure the onRender of withOnyx does this tell us anything about how long withOnyx() took to gather the data before rendering it's wrapped component?

No this only measures the time it took to render or update the component

Can you explain where this batching is happening and how the data collected (either mine or yours) supports it? Not sure I am following, but would be interested in hearing the expert explanation.

In my data here https://github.com/Expensify/App/issues/4116#issuecomment-883371384 you can see different start times but the same commit time I'm not an expert but here's short article: https://techdoma.in/react-16-tutorial/what-are-render-phase-and-commit-phase-in-react (it's for react-dom but the principle is the same in native)

React keeps a Virtual DOM. As components render React creates a diff of changes that need to be made to the actual DOM, it would not send updates on the moment, but wait for renders to finish and only then commit and apply a single precise patch to the DOM

I would like to propose that we add some kind of logging to withOnyx() that logs out which component has mounted and how much time it spent gathering data from Onyx. I think this will help us:

identify areas where we can remove those subscribers entirely

think about whether we need to share the data another way

Thoughts on whether this would be valuable / the best way to implement it?

The Profiler pattern is easy to apply to any component, and does not modify internals, it can tell us whether we're improving render speed, you can delegate a custom id -> props.profilerId if you want to measure something specific e.g. based on reportId. It's build by React so it has access to their internals which should be more accurate

I'm not very keen on determining how much time it took withOnyx to gather for the data, we have this measured through other means. But if we make a function that will derive the initial state based on the mappings in one go, we could measure its performance

So, it would be wise to not have our individual list items subscribed to Onyx. Or come up with another way to share Onyx data with them.

I'm not certain this will help much - the item contains children that are connected to Onyx as well.

Each translated content is already subscribed to Onyx, and there are like 6 such components per each item It's like the HOC pattern was forced to fit here, it's not suitable. Thanks to the Profiler I've seen 6000+ updates for withLocalize components

It just configures a translator object and passes it down as props, this can be replaced by a lib that connects to Onyx once for the PREFERRED_LOCALE and exports translation functions. Context and hooks is another approach.

The updates planned for Onyx should help keep items or their children connected to the store, but with an improved connection speed

What's the exact implementation for this?

I pushed up a branch here if you want to assess the idea.

I'm not very keen on determining how much time it took withOnyx to gather for the data, we have this measured through other means.

Please let me know if there's some easier way to derive it. Of course, I would appreciate a better solution :) I'm not seeing how to use the profiler to tell the time from: withOnyx mount -> call to setState() which will allow the WrappedComponent to render

I'm not certain this will help much - the item contains children that are connected to Onyx as well.

Haha ok, well then I'd propose that we eliminate the children's subscribers too. And more broadly suggesting that given the current state of things it may not be wise to attach subscribers in situations where we need to render n items efficiently. That could be wrong, but there's an easy way to test. Remove the subscribers and see if there's any improvement.

Each translated content is already subscribed to Onyx, and there are like 6 such components per each item It's like the HOC pattern was forced to fit here, it's not suitable. Thanks to the Profiler I've seen 6000+ updates for withLocalize components. It just configures a translator object and passes it down as props, this can be replaced by a lib that connects to Onyx once for the PREFERRED_LOCALE and exports translation functions. Context and hooks is another approach.

Unsure how this relates to the current topic, but sounds like another thing to look into. 👍

The updates planned for Onyx should help keep items or their children connected to the store, but with an improved connection speed

I look forward to those changes and acknowledge your skepticism. But I wanted to suggest the idea that even the most performant iteration of Onyx imaginable may be less performant than not using it at all 😄

There has been some great back and forth on this issue. But some of it may be better discussed in https://github.com/Expensify/App/issues/4101

I'm going to close this for now for focus, but we can re-open if we still have some specific problem with rendering the ReportActionCompose. Anything else related to more global withOnyx() performance we can maybe bring over to the other issue.

Expensify / App