778599 - Facebook spending a large amount of time in js::NewDenseCopiedArray()

Status: RESOLVED WORKSFORME

(Core :: JavaScript Engine, defect)

Description

[Andrew McCreight [:mccr8]]

I've had this problem for a week or two.  When I leave Facebook open for a few hours, I start getting really high CPU usage, which makes my computer hot, and most of the GCs are TOO_MUCH_MALLOC, which indicates a high amount of allocation.

Here's an SPS profile:
http://people.mozilla.com/~bgirard/cleopatra/?report=f89b6f9590df7ed2ff96336e4ec2d67c9b6d5f1c

It looks like it is spending most of its time (about half) in nsGlobalWindow::TimerCallback, and most of that inside some JS on the FB page.

Closing the FB tab makes the problem go away.

Here's a CC after I closed the tab:

CC(T+33464.3) duration: 336ms, suspected: 256, visited: 66431 RCed and 5883 merged GCed, collected: 65668 RCed and 2802 GCed (68470 waiting for GC)
ForgetSkippable 3 times before CC, min: 2 ms, max: 13 ms, avg: 8 ms, total: 25 ms, removed: 445

There are a reasonable number of C++ things being thrown away by the CC, but not the worst I've ever seen.  I guess I should take a CC log when that happens, I forgot to this time.

Probably not useful but this is what the GCs look like:
GC(T+33376.9) Total Time: 119.7ms, Compartments Collected: 1, Total Compartments: 673, MMU (20ms): 0%, MMU (50ms): 0%, Reason: TOO_MUCH_MALLOC, Nonincremental Reason: malloc bytes trigger, Allocated: 150MB, +Chunks: 0, -Chunks: 0
    Totals: Mark: 83.3ms, Mark Roots: 18.4ms, Mark Weak: 0.3ms, Mark Gray: 1.0ms, Finalize Start Callback: 0.6ms, Sweep: 22.8ms, Sweep Atoms: 8.0ms, Sweep Compartments: 5.5ms, Sweep Tables: 2.5ms, Sweep Object: 0.5ms, Sweep String: 0.1ms, Sweep Shape: 0.6ms, Sweep Discard Code: 0.4ms, Discard Analysis: 2.5ms, Discard TI: 0.3ms, Sweep Types: 2.1ms, Clear Script Analysis: 0.1ms, Finalize End Callback: 7.0ms, End Callback: 13.2ms

Comment 1

[Andrew McCreight [:mccr8]]

Some function q() that is taking up the bulk of the time is spending all of its time inside js::RunScript().  In turn, 3/4 of that is spend inside JaegerShot, and 1/4 inside Interpret.

Digging down further, it looks like a large chunk of the time is being spent on js::array_concat, inside js::NewDenseCopiedArray().

Comment 2

[Andrew McCreight [:mccr8]]

I downloaded the .js file (by seeing the base name in the profile, then looking up the full URL in the source for the page), then looked at the line in the profile.  Prettified, the functions in question are this:

    function p(x) {
        q('onleavehooks', x);
    }
    function q(x, y) {
        window[x] = (window[x] || []).concat(y);
    }

That doesn't look very useful, but hey, there is a concat in there.

Comment 3

[Andrew McCreight [:mccr8]]

Profile I just took: http://people.mozilla.com/~bgirard/cleopatra/?report=e7b07cb2bf1424b4c6aeb5507b87d09394b63564

Comment 4

[Paul Silaghi, QA [:pauly]]

Possible dupe - bug 840112

Comment 5

[Jeff Walden [:Waldo]]

If the concat's spinning on NewDenseCopiedArray a lot, that's because (window[x] || []) has a very large dense initialized length, which means window[x] is likely a very large array.  Smells like a TE bug to me, that whatever's being fed in there isn't being cleared out correctly over time or something.  The value of |x| in that case would probably be informative to a FB engineer.

Comment 6

[Paul Silaghi, QA [:pauly]]

Left Firefox open for couple of hours on Facebook - didn't see any issues, the CPU usage was low.
nightly 2013-06-04, mac os x 10.8.3

Comment 7

[Andrew McCreight [:mccr8]]

I haven't seen this in a long time.