1878224 - On Startup, reading keyboard layout/unicode thingy takes 50ms-80ms on a fast laptop

Status: RESOLVED FIXED

(Core :: Performance, enhancement)

Description

[Mayank Bansal]

https://share.firefox.dev/3Ou9ToR

Look at the highlighted ZwUserToUnicodeEx function in the profile. It caught my eye because among a sea of small things during startup, it was a large single chunk. I am not saying its egregious or anything, but maybe there is something to improve?
On another profile, this function took 80ms

Comment 1

[Mayank Bansal]

Attachment: about:support

Comment 2

[Mayank Bansal]

cc'ing some folks who may have some opinions.

Comment 3

[Markus Stange [:mstange]]

ToUnicodeEx looks really expensive! Is there a way we could avoid it or reduce the number of calls to it?

Comment 4

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

Well, I don't remember the bug number, IIRC, I was asked about the start up performance of KeyboardLayout. I guess that we could put it off until the first WM_KEYDOWN or WM_KEYUP at least. However, I don't know whether it works because it updates keyboard state of OS and restore. Therefore, it could break a dead key sequence. I'll try.

Comment 5

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

Attachment: Bug 1878224 - Put it off to load keyboard layout when first needed r=m_kato!

As far as I've tested on Win 11, we can put it off to load it when first needed
of the keyboard layout data. ToUnicodeEx API changes the dead key state and
it's called a lot in KeyboardLayout::LoadLayout, however, this patch does
not newly call LoadLayout after TranslateMessage API at least while handling
a key message. Therefore, this should be safe but regressions of this change
could be serious, so this makes it enabled only in early beta and earlier for
now.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/26e3ad3bf78e
Put it off to load keyboard layout when first needed r=m_kato

Comment 7

[Serban Stanca [:SerbanS]]

Backed out for causing build bustages.

• Backout link
• Push with failures
• Failure Log
• Failure line: mozbuild.preprocessor.Error: ('$SRCDIR/modules/libpref/init/StaticPrefList.yaml', 14746, 'UNDEFINED_VAR', 'EARLY_BETA_OR_EARLIER')

Comment 8

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

I used wrong macro in the YAML file.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6e2ddbc6f131
Put it off to load keyboard layout when first needed r=m_kato

Comment 10

[pstanciu]

https://hg.mozilla.org/mozilla-central/rev/6e2ddbc6f131

Comment 11

[Mayank Bansal]

Profile from the latest Nightly : https://share.firefox.dev/3SzMEuy
ToUnicodeEx did move slightly ahead in the profile(beginning at 220ms compared to 120ms previously). However, i was hoping that it could be loaded after the UI has loaded completely, effectively making the startup feel faster to the user.

Comment 12

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

Odd, it's called via IMEHandler::ProcessRawKeyMessage, however, it's limited only for key messages. Does the test emulate user key input during the start up?

Comment 13

[Mayank Bansal]

(In reply to Masayuki Nakano [:masayuki] (he/him)(JST, +0900) from comment #12)

Odd, it's called via IMEHandler::ProcessRawKeyMessage, however, it's limited only for key messages. Does the test emulate user key input during the start up?

I dont know enough to answer your question :)
Let me describe my STR to capture the profile:
The profile was captured via the "startup profiling" : https://profiler.firefox.com/docs/#/./guide-startup-shutdown

1. Set MOZ_PROFILER_STARTUP=1 in windows advanced system settings
   1.5 Go to https://profiler.firefox.com/ and enable the profiler button in the menubar
2. Go to the firefox folder
3. Run firefox using the terminal/powershell - .\firefox.exe
4. Firefox starts and profile is captured.

The "startup profiling" "presses" the profiler button in the menubar. Maybe that triggers the keyboard thingy to load early?

I also created a new profile and then captured a startup profile on it : https://share.firefox.dev/3SPazaK . This also shows similar behaviour (i.e. the keyboard thingy is only delayed by 100ms, but still occurs before the UI)

Hope this helps. Happy to run any test builds or share any logs to help diagnose further!

Comment 14

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

Odd, I cannot reproduce it within my environment. However, my environment has IME which changes some behavior, so it could be the reason why I cannot reproduce it. On the other hand, I wonder, it could be possible that you released Enter key on the terminal after Firefox Nightly gets focus. However, I couldn't reproduce it with a long press. So I have no idea.

Comment 15

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

Ah, could you attach the log file of the main process when you get the profile with MOZ_LOG=KeyboardHandler:4,sync and MOZ_LOG_FILE=c:\fx (specify a good place to record the log)?

(Close the firefox immediately with mouse to avoid something your intentional input to be recorded, e.g., passwords)

Comment 16

[Mayank Bansal]

I think the patch is working as intended, but there is something weird about running Firefox from the command line.

1. Profile with running "C:\Program Files\Firefox Nightly\firefox.exe" -MOZ_LOG=KeyboardHandler:4,sync -MOZ_LOG_FILE=%TEMP%\log.txt : https://share.firefox.dev/3UA25FP
2. Profile with running : "C:\Program Files\Firefox Nightly\firefox.exe" : https://share.firefox.dev/3P0hKeb

The first profile clearly shows that the keyboard thingy is loaded only when i click a key. I will attach the logfile generated.
The second profile shows that the keyboard thingy is loaded before the UI is loaded. I could not generate log for this second case - If i manually set the MOZ_LOG parameters via environmental variables, no logfile is generated.

Comment 17

[Mayank Bansal]

Attachment: log.txt.moz_log

Log file generated when the MOZ_LOG is passed via command line

Comment 18

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

Thank you.

According to the log, the following key operations are logged:

1. ArrowUp key press without modifiers
2. Ctrl key is pressed but not released
3. C key is pressed
4. Ctrl key is released

Win32 apps cannot get the input source due to the limitation. Therefore, I'm not sure the source of these keys, but I guess that you installed some system wide utilities which synthesizes them. Do you have any ideas? It seems that the Ctrl + C is caused by a clipboard related utility, but I have no idea about the ArrowUp key press.

Comment 19

[Mayank Bansal]

The ArrowUP key was something i had done consciously to start the keyboard thingy to load. As i said, if is start Firefox normally by clicking the icon, the keyboard thing will only load when i press a key. Which means that the patch is working as intended! The Ctrl+C were done to capture the profile and copy the generated link.
There maybe something else that is broken while starting firefox via the command-line that makes the keyboard load early. But that is probably another bug :)

Just curious but there werent any startup improvement alerts due to this change

Comment 20

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(away 4/27 - 5/6)]

Ah, okay, thank you. Once the widget code can know whether it's ready to handle key messages actually, we could put it off more, but I have no idea and I think that it's not so important.