1424057 - Excessive time spent running JS (in "transitionHandler" function), when clicking rightarrow on Facebook photo viewer

Status: NEW

(Core :: JavaScript Engine: JIT, defect, P2)

Description

[Daniel Holbert [:dholbert]]

We spend ~50% more time than Chrome in servicing the click handler, when the user clicks the right arrow on Facebook's photo album viewer.  (~120ms in Firefox, 80ms in Chrome)

My STR:
 1. View my own facebook page
 2. Click "photos" tab
 3. Click the first photo of me
 4. Start profiling
 5. Click the right-arrow on the right edge of the photo
 6. Stop profiling.

The largest difference I've found is in the "transitionHandler" JS function (in Facebook's JS).  Comparing a Firefox vs. Chrome profile:
 - Firefox spends 45.4ms in transitionHandler, which is mostly running JS.  Profile of that function:
    https://perfht.ml/2nEUpnU

 - In contrast, Chrome only spends 14.99ms in transitionHandler, according to a Chrome 64 DevEdition profile I captured earlier today -- screenshot of that profiler UI: https://bug1388179.bmoattachments.org/attachment.cgi?id=8935487

(You'll have to take my word for it that when I hovered "transitionHandler" there, it told me it was 14.99ms)

Some of our 45.4ms-transitionHandler-call is in style stuff (about 7ms of it) -- bug 1388179 covers that. But it looks like we're running JS for most of that call, so I'm filing this bug on that JS part.

Comment 1

[Daniel Holbert [:dholbert]]

For 16ms of transitionHandler (out of a total 45.4ms), we're in "compileScriptForBaseline": https://perfht.ml/2nEjQGl

That compilation time is longer than the *total* time that Chrome spends running this function.

jonco, could you take a look or suggest someone who could?

Comment 2

[Daniel Holbert [:dholbert]]

Just as another data point -- here's a different profile of the same STR on same machine: https://perfht.ml/2nGMKFs
(nearly same configuration -- only difference vs. comment 0 is that this one was captured with STYLO_THREADS=1, but that doesn't matter, for this bug's purposes)

This profile only shows 8.4ms in compileScriptForBaseline, as shown here: https://perfht.ml/2nF0Hnw
...and 1ms in js::jit::BaselineCompiler::compile, as shown here: https://perfht.ml/2nGhJBG
...and a few other ms with "compile" in the backtrace, for a total of 11.2ms, as shown here: https://perfht.ml/2nICVqW

Comment 3

[Jon Coppeard (:jonco)]

Jan, could you find someone to look into this?

Comment 4

[Kannan Vijayan [:djvj]]

I'll look into this this week and try to get more info.

Comment 5

[Kannan Vijayan [:djvj]]

Finally got around to looking at this.  Ran a few profiles on my machine.  I'm not seeing the heavy compileScriptForBaseline in that step (this is profiling with dev edition).  I saw an incremental GC take up a bunch of time in one profile, but subsequent ones don't have that.

Daniel, how are you measuring the "response time" for that click?  What's the basis for comparison between us and chrome?

Comment 6

[Daniel Holbert [:dholbert]]

(In reply to Kannan Vijayan [:djvj] from comment #5)
> Daniel, how are you measuring the "response time" for that click?  What's
> the basis for comparison between us and chrome?

I wasn't measuring response time -- I was just comparing raw time-measurements for time spent in transitionHandler, between the two profiles.  See comment 0. The Chrome profile was https://bug1388179.bmoattachments.org/attachment.cgi?id=8935487 , and when I hovered "transitionHandler" there, they reported a duration of 14.99ms (vs. our 45.4ms)

Good to know that you're not seeing heavy compileScriptForBaseline time, though. I'll try to reprofile and see if things have improved for me, too...

Comment 7

[Daniel Holbert [:dholbert]]

I just reprofiled (using Nightly) and I'm still seeing a long time spent in transitionHandler - 50ms (which makes up 30% of a 169ms "event processing delay" red bar): https://perfht.ml/2CgC5ry

And if I filter the "transitionHandler" time-window for compileScriptForBaseline, I get 18.4ms of hits: https://perfht.ml/2BJ5CZX

So I'm still seeing basically the same behavior as reported in comment 0 / comment 1 (slightly worse, if anything).

Comment 8

[Daniel Holbert [:dholbert]]

Attachment: screenshot showing Chrome profile (taken Feb 22) with time spent in transitionHandler

Here's a Chrome profile that I took today, using their "JavaScript Profiler" (which is now hidden in their devtools "meatball menu" | "More Tools").

As in my original profile, it shows way less time spent in the call to "transitionHandler" (15.2ms) than we spend.

Comment 9

[Daniel Holbert [:dholbert]]

Walking both profiles up a few stack-levels, I see that Firefox is spending 131.2ms in the JS function called "pageListener":
 https://perfht.ml/2BLOYJt
...whereas Chrome's profile shows it only spending 46.9ms there.  (Though compileScriptForBaseline doesn't seem to occupy the bulk of pageListener for us.)

If Chrome's profiler measurements are trustworthy & semi-comparable to ours, then this seems a bit concerning.

(RE responsiveness -- this bug was originally spun off of bug 1388179, which was spun off of bug 1381383. All of which is just pretty much about profiling this particular set of STR & looking in the profile for jank & things that seem optimizable.  And I filed this bug not for a particular responsiveness issue, but rather just because we've got a red jank bar & Chrome's significantly-better profile measurements seems to demonstrate that we could be doing a good deal better.)

Comment 10

[Kannan Vijayan [:djvj]]

Looking at that profile, I see.  I was confused - "compileScriptForBaseline" was not the target.  IonCompileScriptForBaseline is the actual function, and it makes way more sense that an Ion compile would be eating up a bunch of time compared to execution.

This is the second time today that I've identified IonCompile as a major component of execution time in slowdown cases.  I'm not sure if there was a recent regression introduced or something.. or this is a coincidence and the problem has always existed.

We _know_ that IonCompile is slow.  It has a bunch of stuff that is worse than quadratic in time complexity in cases, and can easily get into weird loops.  I wonder if a more aggressive time cutoff for certain operations would be useful here.

The real fix for this is to make Ion compilation faster, but that's a more difficult sheep to shear.

Comment 11

[Kannan Vijayan [:djvj]]

Sean, can you take a look at this when you get a next free cycle?  Talked to sdetar and he said you might be able to take a look at it after your current projects.

Comment 12

[Daniel Holbert [:dholbert]]

(In reply to Daniel Holbert [:dholbert] from comment #0)
> My STR:
[...]
>  5. Click the right-arrow on the right edge of the photo

FWIW: here's a profile where I clicked right arrow 3 times (with a few seconds between each click):
 https://perfht.ml/2pJD6AM

I filtered for "transitionHandler", and it looks like each call is on the order of 40ms.

Comment 13

[Daniel Holbert [:dholbert]]

In that latest "3 rightarrow clicks" profile, here's how much of transitionHandler we're spending in IonCompileScriptForBaseline:
 - First click:  13.0ms https://perfht.ml/2ulO8AI
 - Second click:  5.4ms https://perfht.ml/2uoeGl9
 - Third click:   9.2ms https://perfht.ml/2urugfG

This is a bit better than the measurements in comment 7, but still in the teens of ms for the first call at least.

(I'm not sure what this means about us caching compiled results -- the second and third click are better, but not by a ton. *shrug*)

Comment 14

[Steven DeTar [:sdetar]]

Moving to [qf:p1:f67]