952267 - [B2G][Keyboard] Severe input lag occurs when inputting text into the the edit contact form

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::Keyboard, defect, P1)

Description

[KTucker [:KTucker][Inactive 3/4/2016]]

Attachment: Severeinputlag.txt

Description:
When the user is adding a new contact or editing an existing contact, they will notice that when they are typing at a fast rate on the keyboard, the letters are lagging way behind the user's input. Sometimes, the letters don't even show at all even though they were typed by the user. 

Repro Steps:
1)  Updated Buri to Build ID: 20131218004002
2)  Tap on the "Contacts" icon.
3)  Tap on the "+" icon to add a new contact. 
4)  Tap on the "Name" field and immediately start typing a bunch of different letters at a fast rate.
5)  Tap on the "Last name" field and type a lot of letters at a fast rate.

Actual:
Severe lag occurs when typing at a fast rate on the keyboard when entering text into the edit contact form. Sometimes, the letters typed do not appear at all.

Expected:
When the user taps on a letter on the keyboard, it immediately appears in the text field without delay.

Environmental Variables
Device: Buri v 1.3.0 Mozilla RIL
Build ID: 20131218004002
Gecko: http://hg.mozilla.org/releases/mozilla-aurora/rev/369bdbff6c38
Gaia: a99b23e73fe5630a877004746d0e7fcec1b6d653
Platform Version: 28.0a2

Notes:
Repro frequency: 100%
See attached: video clip, logcat

Comment 1

[KTucker [:KTucker][Inactive 3/4/2016]]

Attachment: Keyboardlag.mp4

Comment 2

[gbennett]

I get the worst perf when using the 3rd party keyboard, but just as a side note I really like the 3rd party keyboard for touch accuracy and overall make less mistakes using it.

.:First Broken Build:.
Environmental Variables:
Device: Buri 1.3 mozRIL
BuildID: 20131206040203
Gaia: 8fca2ca67e8a6022fe6ed8cb576e5d59dfb5237f
Gecko: 1401e4b394ad
Version: 28.0a1
RIL Version: 01.02.00.019.102
Firmware Version: 20131115

.:Last Working Build:.
Environmental Variables:
Device: Buri 1.3 mozRIL
BuildID: 20131206040203
Gaia: 8fca2ca67e8a6022fe6ed8cb576e5d59dfb5237f
Gecko: 1401e4b394ad
Version: 28.0a1
RIL Version: 01.02.00.019.102
Firmware Version: 20131115

Comment 3

[Tim Guan-tin Chien [:timdream] (please needinfo)]

Triage: it does not reproduce locally when we tried, maybe this only occurs when the phone is under heavier load? Please clarify and produce reliable reproducible steps.

Noted that keyboard oop did not enabled during the regression window so it is unlikely this issue is caused by any code change there. However, it's possible that Input Method API changes made during the range cause this.

Comment 4

[Jason Smith [:jsmith]]

QA Wanted - Can you double check reproduces on the latest 1.3 & 1.4 builds?

Comment 5

[gbennett]

This does repro on latest 1.4, but not on latest 1.3

Environmental Variables:
Device: Buri 1.3 mozRIL
BuildID: 20140102004001
Gaia: 01e9da49be2cc4bc134eeefc434740d572ec2246
Gecko: 61f553e5db49
Version: 28.0a2
RIL Version: 01.02.00.019.102
Firmware Version: v1.2_20131115

Environmental Variables:
Device: Buri 1.4 mozRIL
BuildID: 20140102040201
Gaia: 67a82f88da231969efa4d22df9fb946abf2cf4df
Gecko: 540d85f60c57
Version: 29.0a1
RIL Version: 01.02.00.019.102
Firmware Version: v1.2_20131115

Comment 6

[Jason Smith [:jsmith]]

So that implies this is a different bug since this was filed before OOP was enabled again for keyboards, as the regressing bug is likely bug 942790. Can you open a new bug for this?

Comment 7

[gbennett]

Of course. The new issue is bug 956125.

Comment 9

[Rudy Lu [:rudyl] (inactive after 2015/7/3)]

I guess we have to leave one of these 2 bugs as open, if this is still reproducible on v1.4 after enabling keyboard OOP, according to bug952267 comment 5.

Comment 10

[Rudy Lu [:rudyl] (inactive after 2015/7/3)]

Before working on this issue, I guess we would need to do profiling first, so adding the dependency.

Comment 11

[Dave Huseby [:huseby]]

Let me grab some profiles and see if it is anything obvious.

Comment 12

[Dave Huseby [:huseby]]

Attachment: laggy keyboard during contact name entry

I can confirm that the lag is present in v1.4 on the hamachi/buri device.  I have some profiles that I'm picking apart now to identify what's taking so long.

Comment 13

[Dave Huseby [:huseby]]

I was profiling this yesterday and noticed that the display list processing seems to be taking a long time.  :mchang suggested I turn on display list dumping to check it out.  Here's is the profile with display list dumps: 

https://people.mozilla.org/~bgirard/cleopatra/#report=6e44f248e6021374ec07267efc14f92f03d0571a

There's something about the built-in keyboard in this instance that causes extremely slow display list processing and therefore slow keyboard event processing.

Comment 14

[Dave Huseby [:huseby]]

Attachment: New Contact Laggy Keyboard profiler capture with display list dumping.

Comment 15

[Dave Huseby [:huseby]]

For comparison, here's the profile when typing in a new SMS message using the same build and test setup.  It's still a little laggy (probably due to instrumentation) but has better performance than when typing in the name of a new contact.

https://people.mozilla.org/~bgirard/cleopatra/#report=a34948fd04c77efd7734ef98c9ac81fbb7e57b75

Doug, I'm seeing your promise code pop up in the profile.  I'm wondering if the new promise async protocol is reducing overall throughput.  I'll know more after I add some more timing code to this build.

Comment 16

[Dave Huseby [:huseby]]

Attachment: New SMS Laggy Keyboard profile with display list dumping

Comment 17

[Mason Chang [Inactive] [:mchang]]

I'm not really that good at reading display lists yet. Roc or BenWa, do you see anything that would cause long display list processing in the profile from comment 13? Thanks! If so, I'd also be greatly interested to see what you're looking for.

Comment 18

[Benoit Girard (:BenWa)]

Note that in those profiles most of the time is spent dumping the display list. I don't see a profile on the bug collected without the display list dump to show the original cost without the display list dump overhead.

I'm estimating (by subtracting the samples spent in dumping the display list) that the display list is still taking 10ms+ to calculate which is high for so few display item. I don't know why the cost would be so high.

Comment 19

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Got a (In reply to Dave Huseby [:huseby] from comment #16)
> Created attachment 8455044 [details]
> New SMS Laggy Keyboard profile with display list dumping

I don't think this is to do with the keyboard since in this profile the keyboard process does practically nothing. It's all in the Communications process which makes sense since that's where the text is rendered.

There's no actual display list dump attached to this bug, right? It sounds like you're talking about one but I can't find it.

In this profile, looking at Refresh 7 for example, the time charged to nsLayoutUtils::PaintFrame::BuildDisplayList is about 17ms, which definitely sounds excessive. So I'd like to figure this out with a display list dump.

Comment 20

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Benoit pointed me to the layer tree/display list dump.

One odd thing in the dump for display list #12 is this layer and its contents:

ClientContainerLayer (0x44708000) [clip=(x=0, y=50, w=320, h=170)] [visible=< (x=15, y=65, w=290, h=1136); >] [metrics={ viewport=(x=0.000000, y=50.000000, w=320.000000, h=170.000000) cb=(x=0.000000, y=50.000000, w=320.000000, h=170.000000) viewportScroll=(x=0.000000, y=0.000000) displayport=(x=0.000000, y=0.000000, w=320.000000, h=1151.000000) critdp=(x=0.000000, y=0.000000, w=320.000000, h=768.000000) scrollableRect=(x=0.000000, y=0.000000, w=320.000000, h=1151.000000) scrollId=5 }] [scrollParent=3]

containing

ScrollLayer 4479ea50(Block(div)(1)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(0,0,0,0) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 44791208(Block(a)(1)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(1530,8070,4140,1020) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 447fad08(Block(p)(1)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(7800,4470,8700,1260) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 447ac5d8(HTMLButtonControl(button)(3)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(0,0,0,0) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 447acaa0(Block(p)(3)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(7800,7470,4560,1260) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 447ad1c8(Block(p)(1)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(1800,10470,4200,1260) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 44d551d8(FieldSet(fieldset)(1)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(1800,14490,2940,1260) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 44d57c08(Block(p)(1)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(1800,17430,2760,1260) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 44d56218(nsTextControlFrame) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(1800,20430,3060,1260) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 44d570d8(HTMLButtonControl(button)(3)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(0,0,0,0) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 44d55ae8(HTMLScroll(span)(0)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(0,0,0,0) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000
ScrollLayer 447aefe8(HTMLButtonControl(button)(3)) bounds(0,3000,19200,10200) visible(0,0,0,0) componentAlpha(1740,23490,4620,1260) clip(0,3000,19200,10200) (scrollframe 4479e268 scrolledframe 4479ea50) layer=44708000

and a bunch more.

None of these nsDisplayScrollLayers have any children. Their children have been placed in a sibling ThebesLayer. That doesn't make much sense. Some of them (especially ones for <p> elements) actually don't have any corresponding children in a ThebesLayer so I don't know why we're creating an nsDisplayScrollLayer wrapper around nothing. In general I'm not sure why we get this display list/layer structure. As to why we're generating all these ScrollLayers in the first place, I suspect it's because all these frames are abs-pos children of the scrolling frame; is that right? Reducing the amount of abs-pos on these frames, or setting z-index:0 on the outermost abs-pos/rel-pos containers that are children of the scrolled element, might help.

Bug 967844 should reduce the display item creation here.

Bug 967844 might speed this up.

Comment 21

[Dave Huseby [:huseby]]

Here's a profile without the display lists:

https://people.mozilla.org/~bgirard/cleopatra/#report=c506bbae28bc08c1ea080011d271e7a80a5b7af5

So if you look at the comms app, it's spending a lot of time in the refresh driver trick doing paints.  That in turn is lagging out the processing of the async promise messages coming from the keyboard.  That's why the keyboard spends most of it's time idle (epoll_wait).  The problem we've got here is that the keyboard painting is too expensive.

Comment 22

[Benoit Girard (:BenWa)]

That's analysis sounds good to me. But don't forget that we're spending about 1/3 of our time in non RD::Tick code in 'fa_handleEvent'.

I'd suggest trying to simplify the keyboard app to be less complex. A good goal might be to try to get simpler display list. Display Items each have different costs but if we can get it substantially smaller we would likely make the ticks cheaper.

Comment 23

[Dave Huseby [:huseby]]

Dave will read Comment 20 above?  We're having a problem with the display list that the markup/css for the keyboard is generating.  The overly complex display list is slowing down the text entry considerably.  What do you think can be done to simplify the keyboard and speed things up?

Comment 24

[David Flanagan [:djf]]

Dave,

I'm not very familiar with the way the keyboard is actually laid out. Forwarding your needinfo request to Tim who can answer himself or pass it on to Rudy or Jan

Comment 25

[Tim Guan-tin Chien [:timdream] (please needinfo)]

I have not yet spend a lot of time on understanding the keyboard DOM tree and styling but in the control/interaction logic (previously keyboard.js). |git count| gives the following output:

$ g count -- apps/keyboard/js/render.js
    25  salva
    23  Rudy Lu
    21  lodr
    19  Timothy Guan-tin Chien
    15  Jan Jongboom
    15  Alberto Pastor
    14  David Flanagan
    11  Ismael González

$ g count -- apps/keyboard/style/keyboard.css
    60  Ismael González
    34  Rudy Lu
    20  lodr
    17  Alberto Pastor
    15  Vivien Nicolas
     9  David Flanagan
     9  Jan Jongboom

Comment 26

[Dave Huseby [:huseby]]

salva, please Comment 20 and see if you can fix the markup on the keyboard so that the generated display lists aren't as big/costly.

can I assign this bug to you?  if not, who should take this?

Comment 27

[Dave Huseby [:huseby]]

oops, forgot ni?

Comment 28

[Salvador de la Puente González [:salva]]

(In reply to Dave Huseby [:huseby] from comment #26)
> salva, please Comment 20 and see if you can fix the markup on the keyboard
> so that the generated display lists aren't as big/costly.
> 
> can I assign this bug to you?  if not, who should take this?

Sorry for the delay. I will take a look. Assigning to me.

Comment 29

[Dave Huseby [:huseby]]

Any update on this bug?

Comment 30

[Salvador de la Puente González [:salva]]

No, sorry. I'm really busy with certification and 2.0 blockers.

Comment 31

[Doug Sherk (:drs) (inactive)]

The request here is very out of date, but FWIW my async code hasn't landed. I'll be getting back to it at some point.

Comment 32

[Kartikaya Gupta (email:[e-mail])]

Note that bug 967844 recently landed on master and was supposed to help with this; can somebody re-test to see if this issue still persists?

Comment 33

[Tim Guan-tin Chien [:timdream] (please needinfo)]

John, this is something to take over if you are interested.

Comment 34

[Bobby Chien]

Not affected in master/foxfooding.

-----

Build ID               20150707033152
Gaia Revision          e6506d68e01489b57616f8b74e8773f938ce62b3
Gaia Date              2015-07-06 18:14:41
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/e271ef4c49ae
Gecko Version          42.0a1
Device Name            aries
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.worker.20150619.224059
Firmware Date          Fri Jun 19 22:41:08 UTC 2015
Bootloader             s1

Comment 35

[BMO Automation]

Firefox OS is not being worked on