1488435 - Significant key input delay when typing on large Google Docs

Status: NEW

(Core :: JavaScript Engine, defect, P3)

Description

[:Dominik Strohmeier [:dstrohmeier]]

We experience a significant key input delay on both Nightly and Release for Google Docs. This issue is most prominent on large docs.

To reproduce:
Open a big Google Doc. Wait for it to be loaded completely.
Start typing. The problem is more pronounced within the first 60-180sec after loading and will get less severe, but still perceivable afterwards.

Here's a profile recorded to capture the issue on currently Nightly: https://perfht.ml/2NdbaCc

Comment 1

[Vicky Chin [:vchin]]

Just wanted to add that I was previously on the 2018-08-18 build of Nightly and it took 20-30s for the input delay to no longer be noticeable. However, on the latest nightly build 2018-09-04 it took around 45s.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

Need some example Google Doc here.

And the performance profile shows this is all JS.

Comment 3

[Randell Jesup [:jesup] (needinfo me)]

https://docs.google.com/document/d/1CwPnZ7NnzzIt_UjqhaESbgWyI8VRDDzUQA_le9qaeG0/edit?usp=sharing

typing in it: https://perfht.ml/2PYpb5n

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

(100's of ms of time to process key events, almost all spent in JS/ION/etc).  In some cases near 500ms.  It *seems* to be worse with the gecko profiler enabled -- and vchin indicates it regressed between 8/18 and now (though it wasn't wonderful then).  Note edge and chrome are both very snappy here.

This is a perf profile (with --enable-perf) of that.  lots of JS/ION stuff, lots of JS Helper action
Content Mainthread perf profile: https://perfht.ml/2Q5Iz0g    Random JS Helper (nearly 200ms): https://perfht.ml/2Q5uZtS   mostly in FlagAllOperandsAsHavingRemovedUses (it's compiling..)

This is a Gecko Profiler look at it: https://perfht.ml/2Q5YBHw  with 125-250ms keypress events and 500-1s+ event processing delays

Note that it *seems* that Gecko Profiler on makes it worse.  Not 100% confirmed.

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

Finding the regression range should be always the first step in regression bugs.

Comment 6

[Ted Campbell [:tcampbell]]

I see a few InstanceOf on unboxed objects that cannot attach ICs. We are planning to remove the unboxed object mechanism though.

Comment 7

[Vicky Chin [:vchin]]

(In reply to Olli Pettay [:smaug] from comment #5)
> Finding the regression range should be always the first step in regression
> bugs.

I tried to roll back to a previous build of Nightly and can't reproduce the good behavior anymore. So it may not be a recent regression after all.

Comment 8

[Ted Campbell [:tcampbell]]

I suspect this is a code or build change on their end.

Comment 9

[Andrew Overholt [:overholt]]

(In reply to Ted Campbell [:tcampbell] from comment #8)
> I suspect this is a code or build change on their end.

If we have specific questions about this, we can ask Steve Saviano (he's responsive here on Bugzilla).

Comment 10

[Vicky Chin [:vchin]]

(In reply to Ted Campbell [:tcampbell] from comment #8)
> I suspect this is a code or build change on their end.

Steve, are you aware of any changes leading to this input delay? We notice input delays on Chrome as well.

Comment 11

[Steven Saviano]

Hmm, could be one larger item. Will investigate on Docs-side and report back.

Comment 12

[Jon Coppeard (:jonco)]

I noticed some long GC slices marking weak references when profiling this, so making bug 1167452 a dependency.

Comment 13

[Steven Saviano]

Is there a sample doc that could be shared? (view only is fine and I can make a copy)

Comment 14

[Randell Jesup [:jesup] (needinfo me)]

External doc with nothing sensitive(first few pages repeated about 50 times - ~147 pages):
https://docs.google.com/document/d/1CBF65WS71QOC4XiUH-KT2ZGDTp5ieSMSqC-d1NfoFCw/edit#

Comment 15

[Randell Jesup [:jesup] (needinfo me)]

CCing Bruce Dawson because it's possible he'd be interested (though this isn't Windows-specific)

Comment 16

[Philipp Weis]

Thanks Randell for sharing the doc! Agree this feels slow (not just in Firefox btw). We're investigating on our end to see what we can improve.

Comment 17

[Kannan Vijayan [:djvj]]

I'm pretty sure this is a dup of bug 1478104.  The patch there fixes the issue for (DRASTICALLY improves the experience).  I don't want to close as dup unilaterally though.

Comment 18

[Kannan Vijayan [:djvj]]

To clarify my comment: bug 1478104 identifies the same issue on the same doc, and the patch fixes the issue.

Comment 19

[Randell Jesup [:jesup] (needinfo me)]

We have a doc in this bug that's visible to externals, so we should use that as our "example" case to point to if we dup (and move over the dependent bugs we attached to this one). Or perhaps better, rename the other one about JIT tuning, and make it one of the dependencies of this bug.  It doesn't matter much so long as we don't lose track of any of the ideas/bugs here.

I did a quick measurement of this with the patch from bug 1478104.  keypress events that were 125-250+ms (and some near 500ms) are now ~50-90ms (most 55-65 or 70), which is a 2-3x improvement.  We're still maybe 50% slower than Chrome, but we had been 150-400% slower.

Comment 20

[Jason Orendorff [:jorendorff]]

Using these steps:

• enable profiler
• click the link in comment 14
• click in the table on the first page
• type for 20 seconds or so
• capture profile
• in perf.html, click on the "Web Content" process (only one has significant activity during the profile).

On my machine, we're idle 32% of the time; and 27% of total time is spent under js::jit::IonGetPropertyIC::update (doing actual property lookups), and more than half of that (18% of the total) is on a single stack. This made me wonder if it might be actionable as a JS JIT bug, but:

<djvj> jorendorff: P3. Not pageload, and it only shows up on huge docs. Also, doing further perf improvements on it probably requires a rethink of how we structure objects and sparse arrays.

Leaving P1 for now because it's hard to buy that this is really P3, even if the JS engine side of things is too hard to tackle. There's still the 32% idle time.

Comment 21

[Kannan Vijayan [:djvj]]

Jason - one thing to look at is how many of the new IC updates are happening due to post-GC re-generation of ICs.

Comment 23

[Dan Mosedale (:dmosedale, :dmose)]

@mkaply, maybe this is something that should block one of the enterprise-tracking bugs, since it seems like it could be a deal-breaker for some enterprises?

Comment 24

[Mike Kaply [:mkaply]]

Good call. I'm surprised this is still something we haven't fixed.

Comment 25

[Randell Jesup [:jesup] (needinfo me)]

Updated profile (taken with eventDelay data):
https://perfht.ml/2NIS8D5

Comment 26

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Content process event delays during typing

Comment 27

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Content process event delay during reload of the page

Comment 28

[Randell Jesup [:jesup] (needinfo me)]

reload of the page: https://perfht.ml/36Zwims

Comment 29

[Stephen Donner [:stephend] Not actively reading bugmail]

Mass-removing myself from cc; search for 12b9dfe4-ece3-40dc-8d23-60e179f64ac1 or any reasonable part thereof, to mass-delete these notifications (and sorry!)

Comment 30

[Jan de Mooij [:jandem]]

This may be a bit better now with Warp. GDocs had a lot of IonBuilder time on the main thread and Warp should have less of that + it runs off-thread.

Comment 31

[Sean Feng [:sefeng]]

Just to provide a data point about how chrome is better than us.

Firefox: https://share.firefox.dev/2T5BrH7
Chrome: https://share.firefox.dev/3vagyIR

Input event handlers on this gDoc will execute an a function, it generally took about 80 - 110ms in Firefox, and about 30 - 70ms in Chrome.

Comment 32

[Iain Ireland [:iain]]

This profile is all property lookup. We're spending 20%+ of our time in NativeGetProperty and NativeGetPropertyNoGC. It will be interesting to see if these numbers change once Jan's reshape work lands.

Comment 33

[Mayank Bansal]

Worthwhile to reprofile again now that bug 1704430 has been resolved fixed?

Comment 34

[Markus Stange [:mstange]]

It's still pretty bad. https://share.firefox.dev/3t3d3WI

In Firefox, each key event handler takes around 35ms on my fast machine. In Chrome, each key event only takes 16ms.

Comment 35

[Iain Ireland [:iain]]

Now we're spending 10-15% of our time in NativeGetProperty and NativeGetPropertyNoGC, and a similar amount of time in PropMapTable::lookupRaw. The total percentage of time spent looking up properties seems comparable to before, to the extent that it's possible to compare two profiles taken months apart on different machines.

Jan's work on Watchtower might help?