Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
jsamr opened this issue Jul 16, 2021 · 21 comments
Closed

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

jsamr opened this issue Jul 16, 2021 · 21 comments
Labels
Monthly KSv2 Planning Changes still in the thought process

Comments

@jsamr
Copy link
Collaborator

jsamr commented Jul 16, 2021 •
edited
Loading

If you haven’t already, check out our contributing guidelines for onboarding and email [email protected] 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 #3957 (comment) for instructions. This excerpt takes commits relevant to one withOnyx(ReportActionCompose) instance, child of cell with key 70797025.

SHOW LOG
19
Renders withOnyx(ReportActionCompose), first render
24
Renders withOnyx(ReportActionCompose), because betas state changed
25
Renders withOnyx(ReportActionCompose), because comment state changed
26
Renders withOnyx(ReportActionCompose), because modal state changed
27
Renders withOnyx(ReportActionCompose), because network state changed
28
Renders withOnyx(ReportActionCompose), because myPersonalDetails state changed
29
Renders withOnyx(ReportActionCompose), because personalDetails state changed
30
Renders withOnyx(ReportActionCompose), because reportActions state changed
31
Renders withOnyx(ReportActionCompose), because report state changed
76
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

image

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

  1. Assess why blockedFromConcierge is fired 3.7 seconds after the first burst ending at c31
  2. Assess why report and reportActions are emitted multiple times for the same cell
@jsamr jsamr added the AutoAssignerTriage Auto assign issues for triage to an available triage team member label Jul 16, 2021
@MelvinBot
Copy link

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

@MelvinBot MelvinBot removed the AutoAssignerTriage Auto assign issues for triage to an available triage team member label Jul 16, 2021
This was referenced Jul 16, 2021
Closed
Closed
@marcaaron
Copy link
Contributor

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.

@marcaaron
Copy link
Contributor

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?

@parasharrajat
Copy link
Member

I suggest we break it down into sub-components.

@jsamr
Copy link
Collaborator Author

jsamr commented Jul 16, 2021

@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.

@kidroca
Copy link
Contributor

kidroca commented Jul 16, 2021 •
edited
Loading

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

@marcaaron
Copy link
Contributor

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.

@marcaaron
Copy link
Contributor

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.

@jsamr
Copy link
Collaborator Author

jsamr commented Jul 19, 2021 •
edited
Loading

@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.

@marcaaron
Copy link
Contributor

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).

@quinthar
Copy link
Contributor

quinthar commented Jul 19, 2021 via email

@michaelhaxhiu michaelhaxhiu added the Planning Changes still in the thought process label Jul 20, 2021
@michaelhaxhiu michaelhaxhiu assigned jsamr and unassigned michaelhaxhiu Jul 20, 2021
@marcaaron
Copy link
Contributor

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.

@marcaaron

This comment has been minimized.

Sign in to view
@quinthar
Copy link
Contributor

quinthar commented Jul 20, 2021 via email

@kidroca
Copy link
Contributor

kidroca commented Jul 20, 2021 •
edited
Loading

@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

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) args
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

@kidroca
Copy link
Contributor

kidroca commented Jul 20, 2021

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: Better Chat Virtualization Config #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)

@marcaaron
Copy link
Contributor

marcaaron commented Jul 20, 2021 •
edited
Loading

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?

@marcaaron
Copy link
Contributor

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.

@MelvinBot MelvinBot added the Monthly KSv2 label Jul 20, 2021
@kidroca
Copy link
Contributor

kidroca commented Jul 20, 2021

@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 #4116 (comment) 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

@marcaaron
Copy link
Contributor

marcaaron commented Jul 21, 2021 •
edited
Loading

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 😄

@marcaaron
Copy link
Contributor

There has been some great back and forth on this issue. But some of it may be better discussed in #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.

@marcaaron marcaaron mentioned this issue Aug 11, 2021
Merged
5 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Monthly KSv2 Planning Changes still in the thought process
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@quinthar @jsamr @kidroca @MelvinBot @michaelhaxhiu @parasharrajat @marcaaron