1443755 - [E10S A11Y] Make Twitter faster with NVDA

Status: RESOLVED FIXED

(Core :: Disability Access APIs, defect, P2)

Description

[Marco Zehe (:MarcoZ)]

There is a notable performance difference with E10S vs. Non-E10S Firefox a11y when using the Twitter web interface. This is with a build that contains bug 1434822, which made a lot of things faster already. The problem is as follows:

1. With NVDA running, load Twitter.
2. Once you have a fully loaded Twitter, with 50 or so tweets, refresh the NVDA virtual buffer with NVDA+F5.

Result on my machine: Buffer load took 1.376 sec, 20780 chars.

3. Turn off NVDA's browse mode with NVDA+SpaceBar, and use the J and K keys to navigate tweets. Notice that reaction is quite OK with respect to the time between pressing the key and speaking the newly highlighted tweet.
4. Once a new tweet arrives, press Period to refresh.

Result: Even if there's only one new tweet, this takes approximately 4 seconds before NVDA will speak the newly focused/highlighted tweet at the top.

5. Turn browse mode (virtual buffer) back on with NVDA+Space, and refresh the buffer.

Result on my machine: Buffer load took 1.453 sec, 21315 chars.

6. Turn E10S off by setting browser.tabs.remote.autostart to false in about:config.
7. Repeat the above steps.

Results:
- After step 2: Buffer load took 0.531 sec, 19795 chars.
- After step 4: New tweet is read almost instantaneously after pressing Period.
- After step 5: Buffer load took 0.555 sec, 20366 chars.

So the main regression here is the fact that it takes about 4 seconds to refresh tweets when E10S is on, e. g. after pressing Period.

Comment 1

[James Teh [:Jamie]]

I threw some logging into NVDA's vbuf backend to see how many updates it's doing. I pressed "." to update tweets and it took about 4 seconds to report something. Here's what it logged. I haven't analysed this yet, but we're certainly doing a lot of rendering... and there are several separate renders, which means the events were spread out over more than 100 ms.

IO - inputCore.InputManager.executeGesture (16:48:05.490):
Input: kb(desktop):.
INFO - RPC process 3364 (firefox.exe) (16:48:05.647):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
Updating 39 subtrees

INFO - RPC process 3364 (firefox.exe) (16:48:05.677):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
Update complete

INFO - RPC process 3364 (firefox.exe) (16:48:05.815):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
Updating 50 subtrees

INFO - RPC process 3364 (firefox.exe) (16:48:05.900):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
Update complete

INFO - RPC process 3364 (firefox.exe) (16:48:06.433):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
Updating 51 subtrees

INFO - RPC process 3364 (firefox.exe) (16:48:06.500):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
Update complete

INFO - RPC process 3364 (firefox.exe) (16:48:06.617):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
Updating 1 subtrees

INFO - RPC process 3364 (firefox.exe) (16:48:07.865):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
Update complete

INFO - RPC process 3364 (firefox.exe) (16:48:07.934):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
Updating 2 subtrees

INFO - RPC process 3364 (firefox.exe) (16:48:09.303):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
Update complete

INFO - RPC process 3364 (firefox.exe) (16:48:09.303):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
Updating 0 subtrees

INFO - RPC process 3364 (firefox.exe) (16:48:09.303):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
Update complete

INFO - RPC process 3364 (firefox.exe) (16:48:09.319):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
Updating 0 subtrees

INFO - RPC process 3364 (firefox.exe) (16:48:09.319):
Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
Update complete

IO - speech.speak (16:48:09.404):
Speaking [LangChangeCommand ('en_GB'), u'level 1  Mike Murawski @ murawski27 Ever wonder what would happen if an art museum invited visitors to write on the walls? (this is what it looks like after just 5 days) part of \u201cConstruct\u201d by artists keyon gaskin & sidony o\u2019neal invites visitors @PDXArtMuseum to make marks in antiseptic environment of a museum 6 retweets 10 likes 2 hours ago  1 of 41']

Comment 2

[Marco Zehe (:MarcoZ)]

(In reply to James Teh [:Jamie] from comment #1)
> I threw some logging into NVDA's vbuf backend to see how many updates it's
> doing. I pressed "." to update tweets and it took about 4 seconds to report
> something. Here's what it logged. I haven't analysed this yet, but we're
> certainly doing a lot of rendering... and there are several separate
> renders, which means the events were spread out over more than 100 ms.

And two of them look like almost the whole document was rerendered. But let's start from the top:

> IO - inputCore.InputManager.executeGesture (16:48:05.490):
> Input: kb(desktop):.
> INFO - RPC process 3364 (firefox.exe) (16:48:05.647):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
> Updating 39 subtrees
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:05.677):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
> Update complete
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:05.815):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
> Updating 50 subtrees
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:05.900):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
> Update complete

This second one looks like a full list of tweets update.

> INFO - RPC process 3364 (firefox.exe) (16:48:06.433):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
> Updating 51 subtrees
>
> INFO - RPC process 3364 (firefox.exe) (16:48:06.500):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
> Update complete

And again. This time with one tweet more. So the list of tweets alone causes two re-renders when it updates.

> INFO - RPC process 3364 (firefox.exe) (16:48:06.617):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
> Updating 1 subtrees
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:07.865):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
> Update complete

From the time, this looks like a whole document rerender.

> INFO - RPC process 3364 (firefox.exe) (16:48:07.934):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
> Updating 2 subtrees
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:09.303):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
> Update complete

And this almost looks like two document rerenders. Or things just below the document node that cause huge parts to be rerendered.

> 
> INFO - RPC process 3364 (firefox.exe) (16:48:09.303):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
> Updating 0 subtrees
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:09.303):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
> Update complete
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:09.319):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 188:
> Updating 0 subtrees
> 
> INFO - RPC process 3364 (firefox.exe) (16:48:09.319):
> Thread 2352, build\x86_64\vbufBase\backend.cpp, VBufBackend_t::update, 220:
> Update complete

No idea what these might be. But they don't play a significant part timewise.

Comment 3

[Marco Zehe (:MarcoZ)]

Some more information: Chrome and NVDA are very fast with Twitter in focus mode. Focus changes are snappier, and loading new tweets is, too.

Comment 4

[James Teh [:Jamie]]

Attachment: Twitter update event log for one new tweet.

When updating with just one new tweet, there are a huge number of events. In this log, there are 181 events in total. A lot of them are changes to the times for each tweet. First, we fire textRemoved events for all the tweet times, and we then fire textInserted events for all of them. However, they're far enough apart in time that NVDA's buffer update delay (100 ms) elapses before they all get fired and we thus end up with several separate buffer updates.

Comment 5

[James Teh [:Jamie]]

Attachment: NVDA patch to log buffer events.

For reference, here's the patch I used to generate the event log. Note that this logs event ids; I manually search/replaced ids with names in the log for my own sanity.

Comment 6

[alexander :surkov (:asurkov)]

(In reply to James Teh [:Jamie] from comment #4)
> Created attachment 8960579 [details]
> Twitter update event log for one new tweet.
> 
> When updating with just one new tweet, there are a huge number of events. In
> this log, there are 181 events in total. A lot of them are changes to the
> times for each tweet. First, we fire textRemoved events for all the tweet
> times, and we then fire textInserted events for all of them. However,
> they're far enough apart in time that NVDA's buffer update delay (100 ms)
> elapses before they all get fired and we thus end up with several separate
> buffer updates.

should we revisit bug 1301829 again then?

Comment 7

[James Teh [:Jamie]]

Given the number of text events, I had Marco disable SyncTextChangeEvent to see if this improves things. Aaron and I have always suspected this could be a bottleneck, but never found a use case that proved it. With this disabled, the lag is about half the time, so I think it's worth investing time in a patch which only uses SyncTextChangeEvent for live regions.

Comment 8

[James Teh [:Jamie]]

(In reply to alexander :surkov from comment #6)
> should we revisit bug 1301829 again then?

It's certainly worth a try, though given the amount of time between some of the events, it's hard to say whether it will help. Some of the changes may be so far apart that our refresh driver sees them as separate updates, in which case this may not help at all. Still, it'd be good to try this if it's possible to come up with a rough patch that doesn't involve too much time investment. :)

Comment 9

[James Teh [:Jamie]]

This is resolved by Cache the World, which is enabled by default in Firefox 113.