1365835 - Lots of time spent in createScriptForLazilyInterpretedFunction() when playing a youtube video

Status: NEW

(Core :: JavaScript Engine, enhancement, P5)

Description

[(no longer active)]

I came across this when profiling the youtube video playback use case of the Quantum Release Criteria in bug 1363354: https://perfht.ml/2qu1zL5.  Here we spend 21ms in this function.  In this other profile from the same use case, we spend 104ms: https://perfht.ml/2qtVEpt

Naveed, can you please find an owner for this please?

(In general I see this function come up really frequently in profiles -- I know it's the lazy parsing trade-off, but thought I'd mention it.)

Comment 1

[Jean Gong :jgong]

Sean, Please take a look at Ehsan's profiling info for further analysis to see if have existing bugs on this issue.

Comment 2

[Jean Gong :jgong]

Sean, Can you please take a look at profile attached to this bug. Thanks,Jean

Comment 3

[Sean Stangl [:sstangl]]

It looks like this could just be a rounding error in the profiler.

The profiler is attributing 104ms to stacks with createScriptForLazilyInterpretedFunction(). In the profile that function is called 104 separate times. Each occurrence is marked as taking exactly 1.0ms. In each of those occurrences, 100% of "self" time is almost always blamed to zlib's inflate_fast / MOZ_Z_INFLATE_FAST().

I'll see if I can get better timing information for that function by other means.

Comment 4

[Sean Stangl [:sstangl]]

Following the STR in Bug 1363354, I count 2,316 functions that get delazified upon loading the video page. Most of these take so little time that the profiler doesn't pick them up.

Comment 5

[Sean Stangl [:sstangl]]

That number is out of ~7,080 functions shipped in YouTube's base.js, all of which get lazified except for the file-wide IIFE. So the vast majority of functions properly remain lazified.

Comment 6

[Sean Stangl [:sstangl]]

The vast majority of functions take < 0.1ms to delazify; about 80 functions take 0.1 <= x < 0.2ms to delazify; 7 functions take 0.4 <= x <= 0.59ms; none take more; the total cumulative time taken is 64ms, which probably includes some GC.

The functions on the heavier end seem to just be longer, between 300 and 500 characters.

The major files that YouTube ships are "base.js", "common.js", "spf.js", and "watch.js", which seem to have at least one function per line as a minimum possible average. These files have ~10,500 lines between them, and about that many functions. On repeated runs, we delazify about ~2000 functions, with the majority remaining lazified.

The situation looks alright to me in terms of how aggressive we are in lazifying.

Comment 7

[Sean Stangl [:sstangl]]

For posterity, SourceCache decompression occupies just 14% of the total execution time of createScriptForLazilyInterpretedFunction().

Every now and then, one of these random small functions will look like it takes significantly longer (~3.25ms spent just in the SourceCache; ~3.43ms total), but that's most likely a GC.

Comment 8

[Nicolas B. Pierron [:nbp]]

I tested this bug, with and without the JavaScript Start-up Bytecode cache, and while I can't spot the symbols of the XDR decoder, I see less stacks with createScriptForLazilyInterpretedFunction (~21ms) compared to when it is disabled (~60ms).

I am not experienced enough with the profiler to know if this is only by luck or if this corresponds to anything real.

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee didn't login in Bugzilla in the last 7 months.
:sdetar, could you have a look please?
For more information, please visit auto_nag documentation.