App: [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 <dl> <dh>19</dh> <dd>Renders withOnyx(ReportActionCompose), first render</dd> <dh>24</dh> <dd>Renders withOnyx(ReportActionCompose), because betas state changed</dd> <dh>25</dh> <dd>Renders withOnyx(ReportActionCompose), because comment state changed</dd> <dh>26</dh> <dd>Renders withOnyx(ReportActionCompose), because modal state changed</dd> <dh>27</dh> <dd>Renders withOnyx(ReportActionCompose), because network state changed</dd> <dh>28</dh> <dd>Renders withOnyx(ReportActionCompose), because myPersonalDetails state changed</dd> <dh>29</dh> <dd>Renders withOnyx(ReportActionCompose), because personalDetails state changed</dd> <dh>30</dh> <dd>Renders withOnyx(ReportActionCompose), because reportActions state changed</dd> <dh>31</dh> <dd>Renders withOnyx(ReportActionCompose), because report state changed</dd> <dh>76</dh> <dd>Renders withOnyx(ReportActionCompose), because report state changed</dd> <dh>192</dh> <dd>Renders withOnyx(ReportActionCompose), because blockedFromConcierge state changed</dd> <dh>193</dh> <dd>Renders withOnyx(ReportActionCompose), because loading state changed</dd> <dh>215</dh> <dd>Renders withOnyx(ReportActionCompose), because reportActions state changed</dd> <dh>220</dh> <dd>Renders withOnyx(ReportActionCompose), because report state changed</dd> </dl>

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

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 21 (16 by maintainers)

Most upvoted comments

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)

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

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.