Closed Bug 992346 Opened 6 years ago Closed 6 years ago

[B2G][Tarako][Keyboard] Keyboard appears with delay after device is restarted

Categories

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

ARM
Gonk (Firefox OS)
defect

Tracking

(blocking-b2g:1.3T+, b2g-v1.3 unaffected, b2g-v1.3T verified, b2g-v1.4 fixed, b2g-v2.0 fixed)

RESOLVED FIXED
1.4 S6 (25apr)
blocking-b2g 1.3T+
Tracking Status
b2g-v1.3 --- unaffected
b2g-v1.3T --- verified
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: sarsenyev, Assigned: janjongboom)

References

()

Details

(Keywords: perf, Whiteboard: [c=effect p= s= u=tarako] [tarako-exploratory])

Attachments

(9 files, 1 obsolete file)

Attached file log442014.txt
Description:
After restarting Tarako device, the keyboard appears with delay for the first time 

Repro Steps:
1) Update a Tarako to BuildID: 20140404004001
2) Restart device
3) Open any app where keyboard is required (i.e SMS or E.me

Actual:
The  keyboard doesn't appear immediately 

Expected:
The keyboard appears immediately 

1.3T Environmental Variables:
Device: Tarako 1.3T MOZ
BuildID: 20140404004001
Gaia: acd18bbd94ebfa534e252a24a75a0617e4b5d5ae
Gecko: 91a1b54da4a6
Version: 28.1
Firmware Version: sp8810

Notes:
The issue reproduces 

Repro frequency: 100% 5/5

See attached: video, logcat

The issue doesn't repro on 1.3 Buri

1.3 Environmental Variables:
Device: Buri 1.3 MOZ
BuildID: 20140401004003
Gaia: 24f562fce468fc948ac9e6185e002c23350cb9ee
Gecko: 0adf24a785f2
Version: 28.0
Firmware Version: v1.2-device.cfg
blocking-b2g: --- → 1.3T?
Keywords: perf
ni? Rudy
Flags: needinfo?(rlu)
seems to work, maybe not the correct place to drop it
Attached file getText_delay.log
At a first glance, you may find that the delay might come from the call to inputContext.getText(), because it would take 2.x seconds waiting for the promise to be fulfilled, as the attached logs showed. 

You may find my branch here for the added dump logs,
https://github.com/RudyLu/gaia/commits/keyboard/launch_time_v1.3t
Flags: needinfo?(rlu)
Attached file no_getText_delay.log
However, after I commented out the call to getText(), I found that keyboard app would wait for the inputcontextchange event for almost 2.x seconds to show the keyboard.

Please refer to the logs attached.

--
Jan, Xulei,

I'm afraid this issue might need some experts from Gecko side to take a look about the timing of getText() and/or inputcontextchange.

Does any of you have bandwidth to check for us?
Thanks in advance.
Flags: needinfo?(xyuan)
Flags: needinfo?(janjongboom)
yxl: Do we not load the keyboard frame scripts (form.js etc.) in 1.3t? Is there even a different Gecko for 1.3t? I thought it was only gaia.
Flags: needinfo?(janjongboom)
I think we have a 1.3t branch for Tarako, but I suppose the forms.js related code should be almost the same as what we have on v1.3 or v1.4. (?)
http://hg.mozilla.org/releases/mozilla-b2g28_v1_3t/
Comment on attachment 8402246 [details] [diff] [review]
Force wakelock in b-2 mochitests to reduce timeouts

wrong bug...
Attachment #8402246 - Attachment is obsolete: true
Might be a dupe of bug 989286.
See Also: → 989286
@Jan, we have done nothing special to v1.3t with the gecko keyboard code. It has the same code with v1.3. So we should have load the keyboard frame scripts (form.js) in 1.3t.

@Rudy, gecko keyboard code of v1.3t is almost the same as the v1.4 and the master, as its commits are all picked from v1.4.

I agree jsmith that it may be a dupe of bug 989286.

It's seems the keyboard frame scripts needs much more time to load on the low cost Tarako devices.
Flags: needinfo?(xyuan)
See Also: 989286
Attachment #8402530 - Attachment mime type: text/x-log → text/plain
We need pref team to look into performance of InputMethod API codebase. If this is 1.3T+'d, we need to put this in priority too. I suspect this hunts us in 1.5 too when keyboard is OOM'd.

Mike, Thinker, would you be able to help?
Flags: needinfo?(tlee)
Flags: needinfo?(mlee)
ni? Marvin/Ravi on performance requirement
Flags: needinfo?(mkhoo)
Flags: needinfo?(rdandu)
Duplicate of this bug: 988609
What I saw was when you kill the keyboard process (OOP enabled), then the frame scripts etc. are only loaded the moment you focus on a new text field. Maybe it's something similar.
Based on "Perception of progress" I would say 1s is our target here.

Hi Ravi,
do you agree with this?
Flags: needinfo?(mkhoo)
Ni? Shelly for further input
Flags: needinfo?(slin)
(In reply to Marvin Khoo [:Marvin_Khoo] from comment #15)
> Based on "Perception of progress" I would say 1s is our target here.
> 
> Hi Ravi,
> do you agree with this?

Well we're certainly not hitting that target right now. The video here is showing the fact that we're taking roughly 3 seconds to get the keyboard to come up.
triage: lets retest on this when other keyboard improvement lands
QAWANTED to make sure we have all the other settings turned off when testing this Bug 991627 - [Tarako] Remove Keyboard settings and dictionaries (edit)
Keywords: qawanted
We'll have someone look at this in our next sprint[1] which starts next Monday, 2014.04.14.

As described and shown in the video this appears to be both "cause & effect" and "perception of progress". I'd agree with Marvin that the virtual keyboard should be launched within 1s. It should begin it's animation with 140ms of touching the text field.

FxOS Responsiveness Performance Goals are:

0 - 140ms: App's icon shows that it's been touched.
0 - 1.00s: App's launch animation started and completed.
0 - 1.00s: App's core interface (e.g. banner and controls) must be loaded and visible.
0 - 1.00s: App's above-the-fold (visible) content or a "Loading..." message must be shown.
0 - 1.25s: App's ready for user interaction (e.g. touch, scroll, etc.)

The above times are cumulative so app icon touch to app interaction-ready is
expected to occur within 1.25s.

We've created a Responsiveness Performance wiki page[2] and will post goals
there. Linked from that page is a spreadsheet[3] we (Gordon UX) has put
together mapping the Taipei team's Tarako Performance Results to our
Responsiveness goals.

[1] https://scrumbu.gs/t/fxos-dev-mlee/2014.04.25/
[2] https://wiki.mozilla.org/B2G/Performance/Responsiveness
[3] http://bit.ly/1sDmepL
Severity: normal → blocker
blocking-b2g: 1.3T? → 1.3T+
Flags: needinfo?(rdandu)
Flags: needinfo?(mlee)
Priority: -- → P1
Whiteboard: [tarako-exploratory] → [c=effect p= s= u=tarako] [tarako-exploratory]
Here's some numbers (focus on browser input field) for first render. With the patches from bug 994000 included already.

From focus (in browser) to renderKeyboard call takes 255 ms.
From renderKeyboard to done rendering takes 1860 ms.

So we should be able to fix that last call in gaia only code.
render.js getVisualData() takes almost two seconds on Tarako. So let's fix that. I already had a bug tracking that in bug 993427.
Assignee: nobody → janjongboom
See Also: → 993427
The getVisualData call came because at that moment the browser starts to render, so it was false positive.

Alright, so I tracked down what happens, I just have no clue why...

The ENTER symbol makes us wait 1.5 secs or so. On subsequent loads everything is fast. I think the symbol comes from a font that is not in memory or so, and then we'll have to wait until it's loaded. Replacing the symbol with just text fixes the issue.

I disabled all style information, so I have no clue what happens here...
FYI, easy to reproduce. Just replace the ENTER button by the text 'ENTER' and execute:

document.querySelector('*[data-label="ENTER"]').innerHTML = '↵'

Takes 1600 ms.
This patch loads the keyboard symbols on startup, and brings down initial loading time of the keyboard by about 1.5 seconds on my Tarako.
Attachment #8404780 - Flags: review?(rlu)
Part 2 - This makes getVisualData get its data from the DOM, so we don't block the b2g process for 250 ms.
Attachment #8404782 - Flags: review?(rlu)
Flow: focus in browser app -> keyboard gets event -> keyboard is done rendering, sends event to system -> system receives event

With these two patches the time it takes for this flow is ~700 ms. Including the other patches under bug 994000 it goes down to 620-650 ms. The most time is now not spent in keyboard, but in other stuff:

- From focus event in browser to keyboard -> 391 ms.
- Keyboard render time, dispatch to system -> 108 ms.
- System app receives mozbrowserresize event -> 183 ms.

So I think this is as much as I can get out of it.
It was 2500-2600 ms. by the way.
At the first time, gfxFontGrouop::FindFontForChar() finds '↵' from "Droid Sans Fallback":

  // -- otherwise look for other stuff
  *aMatchType = gfxTextRange::kSystemFallback;
  font = WhichSystemFontSupportsChar(aCh, aRunScript);
  return font.forget();

but the other lables are from "Fira Sans OT":

  if (firstFont->HasCharacter(aCh)) {
    *aMatchType = gfxTextRange::kFontGroup;
    return firstFont.forget();
  }
FYI, I think that this was also the reason that I saw a 1.2 second reflow when switching from English -> Chinese. Chinese font probably is not there yet either.
This may be a stupid question, but just curious...

Would it be more memory efficient to use a canvas to draw the return key symbol vs. loading an entire fontface for a single character?
Backspace, SHIFT and globe are also in the typeface... Maybe switch to SVG.
Not too sure about the possibilities of this, but could we get Fira Sans modified to add the carriage return symbol to the typeface at U+21B5? Then it would be as easy as HTML entity ↵
One thing I don't understand is if keyboard.css has specified "Keyboard Symbols" as the font of special-key, why gfxFontGrouop::FindFontForChar() is invoked?
Maybe we need to add quotes around the font name, and it doesn't work because we don't have that.
OK, nvm that doesn't make sense.
Comment on attachment 8404780 [details] [review]
Part 1 - Load keyboard symbols on startup

As our discussion on IRC, this won't work after keyboard frame is OOM'ed.
(Note that keyboard OOP is not enabled on v1.3t, but the frame would be removed when the system app receives memorypressure event). 


Fabrice,

Do you think we could reconsider the case to remove keyboard frame since right now the dictionaries and suggestion functions have been disabled?

Thanks.
Attachment #8404780 - Flags: review?(rlu)
Flags: needinfo?(fabrice)
Here is the profiling results using TaskTracer:

Target scenario: 
The very first launch of keyboard after system rebooted.

Profiling background: 
Restart devices, launch Contacts App, tap on a text field, see the keyboard has fully arisen.

Profiling time stamp:
From the touch event to the end of keyboard's sliding transition.

We found out that the promise resolver in keyboard.js took up the most time, the execution time of this promise resolver is about 3 sec, attachment[a] shows the screenshot of this task on TaskTracer's tool - Isis. This promise resolver does things such as draw keyboard, render keyboard, and build keyboard. Rudy can provide more details about this promise resolver.

Then, after applied Rudy's test patch:
https://github.com/RudyLu/gaia/commits/keyboard/testing_keyboard_launch
(This test patch takes out the actual drawing logic of keyboard, but just simply faking the flag of done rendering to true.)

Turns out that the promise resolver took only 0.03 sec. See attachment[b].

The link of Isis:
http://alivedise.github.io/isis/

Log file of the first keyboard launch:
http://people.mozilla.org/~slin/tasktracer/tt-keyboard-launch-tarako.json

Log file of the same scenario but with Rudy's test patch:
http://people.mozilla.org/~slin/tasktracer/tt-keyboard-fake-launch-tarako.json
Flags: needinfo?(slin)
Comment on attachment 8404780 [details] [review]
Part 1 - Load keyboard symbols on startup

Rudy had a good point that we'll have the same issue when keyboard gets killed due to OOM. I inlined the keyboard font now in keyboard.css instead.
Can you run the same with the 2 patches attached?
Flags: needinfo?(slin)
After applying those two patches, the execution time of that promise resolver is now 0.68 sec.

We also try to measure the time of function doShowKeyboard() in keyboard.js.
Results tell us that without the patches applied, the execution time of that Promise task (mozilla::dom::PromiseResolverMixin) is about 3 sec, but the execution time of function doShowKeyboard() takes only 0.27 sec.

With those patches applied, the execution time of that promise resolver is 0.68 sec, the execution time of function doShowKeyboard() is 0.63 sec.
Flags: needinfo?(slin)
Correct: After applying the two pull requests, four patches in total.
Hmm, that is interesting. Because here there is 425 ms. spent in the render function. That is a lot (more than I see on Tarako, but I don't have debugger attached). Anyway, from the profiler, all time is spent on |getHeight| in render.js:890. Triggered from updateLayoutParams in keyboard.js. The getHeight call has been resolved in bug 993367. If I apply that patch as well (only the tests don't merge cleanly), the only time spent is building up the DOM (buildKeyboardRow), which seems OK.

Can you run the same with patch from bug 993367 applied (has been r+ed already)? Then everything should be smooth sailing.
Flags: needinfo?(slin)
(As we discussed on IRC)

After applying the patch from bug 993367, result shows that the promise resolver takes about 0.27s, and the doShowKeyboard() takes about 0.26s.
Flags: needinfo?(slin)
Jan, you really did an awesome job!
Wiki of TaskTracer:
https://wiki.mozilla.org/TaskTracer

My profiling labels of keyboard launch time:
https://github.com/shellylin/gaia/commits/tt-profile-keyboard-1.3t
(Search for TaskTracerDump: and you'll find the labels)
Flags: needinfo?(tlee)
Status: NEW → ASSIGNED
(In reply to Rudy Lu [:rudyl] from comment #36)
> Fabrice,
> 
> Do you think we could reconsider the case to remove keyboard frame since
> right now the dictionaries and suggestion functions have been disabled?

Let's see where we stand with Jan's patches first.
Flags: needinfo?(fabrice)
We've got a patch in progress here, so I'm going to hold off on the QA testing.
Keywords: qawanted
Comment on attachment 8404780 [details] [review]
Part 1 - Load keyboard symbols on startup

r=me for inlining the font info.

Jan,

Thanks for the great work!
Attachment #8404780 - Flags: review+
This needs to go to 1.4 too.
Jan, please squash the commits before merging and fill the 1.4 approval form. Thanks.
After discussion with Rudy on IRC we're probably not landing part2 for now.
Hi! Jan,

Do you mean part 1 is good enough for Tarako?
What is your plan for part 2?
Thanks.

--
Keven
Attachment #8404782 - Flags: review?(rlu)
Landed in master: https://github.com/comoyo/gaia/commit/2036ef549ac7d968c35454fdd64c5d41576a70ba

The referenced pull request targets 1.3t. Waiting for sheriff to land.

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): Always has been here
[User impact] if declined: Freeze up to 1.8 seconds when keyboard opens for the first time
[Testing completed]: ?
[Risk to taking this patch] (and alternatives if risky): Almost none
[String changes made]: None
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
(In reply to Keven Kuo [:kkuo] from comment #54)
> Do you mean part 1 is good enough for Tarako?
> What is your plan for part 2?
> Thanks.

According to comment 24, part 1 can save us around 1.5 sec, and part 2 saves us for about 0.25 sec.
If we still need part 2 we can create another bug.
v1.3t: https://github.com/mozilla-b2g/gaia/commit/5a5690d6691d3bc23e83d4433b458192f4197a8f

(In reply to Jan Jongboom [:janjongboom] (Telenor) from comment #55)
> Landed in master:
> https://github.com/comoyo/gaia/commit/
> 2036ef549ac7d968c35454fdd64c5d41576a70ba

https://github.com/mozilla-b2g/gaia/commit/2036ef549ac7d968c35454fdd64c5d41576a70ba :P

Looks like we still need uplift approval to land on 1.4, so leaving that alone for now.
Duplicate of this bug: 993354
Enabled following loggings and tested without the patch, FindFontForChar() finds '↵' from "Droid Sans Fallback" before "Keyboard Symbols" is loaded:

export NSPR_LOG_MODULES=textrun:5,textrunui:5,userfonts:5

04-20 14:01:59.160 I/PRLog   (  594): 1074791560[40331080]: userfonts (40367040) added (Keyboard Symbols) with style: normal weight: 600 stretch: 0
04-20 14:05:58.000 I/PRLog   (  594): 1074791560[40331080]: userfonts (40367040) [src 0] loading uri: (app://keyboard.gaiamobile.org/style/fonts/Keyboard-Symbols.woff) for (Keyboard Symbols)
04-20 14:05:58.050 I/PRLog   (  594): 1074791560[40331080]: (textrun) fontgroup: ['Keyboard Symbols',sans-serif,sans-serif] lang: en-us script: 0 len 1 weight: 500 width: 0 style: normal size:  15.00 2-byte TEXTRUN [↵] ENDTEXTRUN
04-20 14:05:58.050 D/TINGf   (  594): gfxFontGroup::FindFontForChar aCh=0x000021b5
04-20 14:05:59.680 I/PRLog   (  594): 1074791560[40331080]: (textrun-systemfallback-common) char: u+0021b5 unicode-range: 30 script: 0 match: [Droid Sans Fallback] time: 1509385us cmaps: 0
04-20 14:06:00.520 D/TINGf   (  594): gfxFontGroup::FindFontForChar #9 Droid Sans Fallback
04-20 14:06:01.210 I/PRLog   (  594): 1074791560[40331080]: userfonts (40367040) [src 0] loaded uri: (app://keyboard.gaiamobile.org/style/fonts/Keyboard-Symbols.woff) for (Keyboard Symbols) gen: 00000002
Verified the fix on Tarako.  The keyboard loaded in about a second.

1.3 Environmental Variables:
Device: Tarako 1.3 MOZ
BuildID: 20140429014002
Gaia: b5adc5a943d3abbd6ab070a47c847f2c24891cc5
Gecko: e9890f5d4709
Version: 28.1
Firmware Version: sp6821
Target Milestone: --- → 1.4 S6 (25apr)
We'll need this on 1.4 as well. Who should I ping for uplifting?
Flags: needinfo?(timdream)
Rudy, please set the approval flag and fill out the form. Thanks.
Flags: needinfo?(timdream) → needinfo?(rlu)
Sorry, I thought Rudy was the author of this bug.

So the way to do it would be set the approval flag on your master patch to request an uplift. Do fill the form should up on the comment field.
Flags: needinfo?(rlu) → needinfo?(janjongboom)
Comment on attachment 8404780 [details] [review]
Part 1 - Load keyboard symbols on startup

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): Initial implementation
[User impact] if declined: 1.5second extra delay every time the keyboard is OOM'ed
[Testing completed]: Yes
[Risk to taking this patch] (and alternatives if risky): Low, no issues came up about the issue and testing seems to be happy about it.
[String changes made]: None
Attachment #8404780 - Flags: approval-gaia-v1.4?
Flags: needinfo?(janjongboom)
blocking-b2g: 1.3T+ → 1.4?
Comment on attachment 8404780 [details] [review]
Part 1 - Load keyboard symbols on startup

putting through triage
Attachment #8404780 - Flags: approval-gaia-v1.4?
Comment on attachment 8404780 [details] [review]
Part 1 - Load keyboard symbols on startup

SPRD not asking for the same in 1.4. Please request for 2.0
Attachment #8404780 - Flags: approval-gaia-v1.4-
blocking-b2g: 1.4? → 1.3T+
Hi Jan,

Sorry but can you please set the request approval for 1.4 again? We have spoken with Preeti to align on some items.

Thanks!
Flags: needinfo?(janjongboom)
Comment on attachment 8404780 [details] [review]
Part 1 - Load keyboard symbols on startup

Re-nom based on last comment.
Attachment #8404780 - Flags: approval-gaia-v1.4- → approval-gaia-v1.4?
Flags: needinfo?(janjongboom)
Attachment #8404780 - Flags: approval-gaia-v1.4? → approval-gaia-v1.4+
You need to log in before you can comment on or make changes to this bug.