1402130 - 800ms of jank while typing in the AwesomeBar

Status: RESOLVED FIXED

(Firefox :: Address Bar, enhancement, P2)

Description

[Mike Conley (:mconley) (:⚙️)]

This is likely a dupe of another bug, but filing just in case.

sancus pointed me at this profile today:

https://perfht.ml/2jNwNLP

Here are the important bits:

https://perfht.ml/2jNpyUf
https://perfht.ml/2jNHRc4

STR, roughly, were:

0) Presumably have a bunch of browsing history at Reddit
1) Focus the AwesomeBar
2) Start typing:

redd

And that was enough to lock up the main thread in the parent process for almost a full second.

Anything useful in these stacks, mak? Are these dupes of things we already know about?

Comment 1

[Florian Quèze [:florian]]

Nothing major jumps at me in these profiles. If we dig deeper, there are lots of 'small' things that together add up to a lot of jank.

122ms of that jank is spent reporting CSS errors to the console when setting the width. I suspect the width being set at http://searchfox.org/mozilla-central/rev/15ce5cb2db0c85abbabe39a962b0e697c9ef098f/toolkit/content/widgets/autocomplete.xml#2401 is somehow negative.

There's 71ms spent in nsDOMWindowUtils::GetBoundsWithoutFlushing (called mostly from adjustSiteIconStart), I find that surprisingly expensive. We must be calling it lots of times, maybe some caching would make sense.

Comment 2

[Marco Bonardo [:mak]]

I imagine the system was busy with something (and here is the ipc jank), otherwise these calls wouldn't take that much, unless it's an extremely slow system.

I see some calls to getBoundingClientRect that should go away with bug 1356532. And probably some style flushes (same).
I see various other getBoundsWithoutFlushing around, like the 2 you pointed out, but it's all stuff needed to keep the layout sane.

There are likely ways to improve the code, but from the (signature incomplete) profile there's no low hanging fruit I can recognize, so we need to check it line by line. Everything that could be done in time for 57 has been done.
Simplifying the autocomplete layout would make it much cheaper, unfortunately the current design with the input field in the middle, the panel as large as the window but its contents aligned with the input field is expensive to draw. We must find a way to implement it in a cheaper way.

We also need more measurements in the wild to understand if the times in this profile are common or not, I didn't see anyone complaining the location bar takes 1s to update lately.

Comment 3

[Marco Bonardo [:mak]]

(In reply to Florian Quèze [:florian] [:flo] from comment #1)
> There's 71ms spent in nsDOMWindowUtils::GetBoundsWithoutFlushing (called
> mostly from adjustSiteIconStart), I find that surprisingly expensive.

there are surely improvements and caching we can do, we concentrated on removing flushes, but the code itself often has many calls that can be avoided (see my simple change that avoided a ton of calls to _handleUnderOverFlow())

Comment 4

[Andrei Hajdukewycz [:sancus]]

(In reply to Marco Bonardo [::mak] from comment #2)
> I imagine the system was busy with something (and here is the ipc jank),
> otherwise these calls wouldn't take that much, unless it's an extremely slow
> system.

I'm the person who did the profiling and experienced the bug: the system's a desktop core i7-6700K that was almost completely idle when this was taken.

Of course, I don't know how common this will be or if there's something specific to my profile, however, I first noticed this immediately on being upgraded to 57 beta, when previously the address bar was very smooth. I don't experience any address bar perf issues on previous versions.

Comment 5

[Marco Bonardo [:mak]]

Thank you for pointing that out. It is really strange, 57 should be quite faster than 56.

I said the above because of that strange 7s ipc pause that made me think Firefox was busy on something.
Florian identified some low hanging fruits in comment 1 that we can fix likely for 57, but we need to check code deeper for other changes.

Comment 6

[Marco Bonardo [:mak]]

Andrei, could you please attach a log from about:support? I'm trying to understand if there's something correlated that we are missing.

Comment 7

[Andrei Hajdukewycz [:sancus]]

Hi, so first of all, I had some add-ons installed and a modification in userChrome.css that I think was causing the negative css width set above. I've removed ALL of my add-ons and cleared that out, and now the jank is down to 600ms. That's still a very noticeable 'lag' while typing that wasn't present before, mind you.

New profiling here: https://perfht.ml/2xzlVXk

Secondly, here is the requested about:support log: https://pastebin.mozilla.org/9067970

Comment 8

[Marco Bonardo [:mak]]

Thank you a lot for the help figuring this out.
Knowing that the css error was not on our side will save us some investigation time.
About:support looks ok, nothing that jumps at my eyes there.

adjustSiteIconStart is still a large part of the time, the idea in bug 1402272 that I just filed should help.
Then we can likely look at the code for micro-optimizations in the whole _appendCurrentResult method.

I still find puzzling that this call causes 600ms of jank by itself :(

Comment 9

[Marco Bonardo [:mak]]

If you would like to try and report improvements, we have a patch in Nightly that may have helped. There's more work to do but it would be nice to understand how much it improved for you.
I suggest using a copy of your profile in Nightly if you are currently on 57, to avoid any "upgrade/downgrade" bugs.

Comment 10

[Marco Bonardo [:mak]]

The patch will be part of 57b6, if you prefer to wait for it, should be out soon.

Comment 11

[Andrei Hajdukewycz [:sancus]]

I apologize for not responding earlier, I've been ridiculously busy the past month. Since Firefox 57 released today, I revisited this and..... it seems to be completely gone now. I'm not sure if the patch mentioned above that went into 57b6 fixed it, or if something in my profile changed to stop triggering an issue, but there are no perceptible delays when searching the awesomebar for reddit urls or anything else that I can see.

I ran the profiler again and the biggest delays appeared to be 40-60ms but after a few attempts it wasn't even consistently that long and didn't show up as a delay at all.

Comment 12

[Marco Bonardo [:mak]]

That's great to hear, I'm going to resolve this, bug 1356532 will stay open for fixing the last known perf issue.