625871 - FF4 Audio Demo getting killed by CycleCollector pauses

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[David Humphrey (:humph)]

We are building a demo for the FF4 release (heavy webgl, audio data api, canvas, js analysis, etc.), which is very complex.  Running with --enable-profiling and shark, we see pauses (sometimes locking the whole browser for many seconds, other times just pausing the animation) that look to be CC related.

I suspect that we are leaking and can fix some stuff on our side.  However, I'm somewhat lost on how to find/fix things, and/or if they can all be fixed on our side.

Compounding this is the fact that I can't post this on the web and point you at it, as it's not public yet.

Any ideas of things I could try would be greatly appreciated.

Comment 1

[David Humphrey (:humph)]

Attachment failed, I've posted the .mshark file here:

http://scotland.proximity.on.ca/dxr/tmp/audio-demo.mshark

Comment 2

[Brendan Eich [:brendan]]

David, you've seen bug 624549 and friends, and Patrick's awesome auto-sharking frame rate monitor, right? I ask only because Patrick's not cc'ed here.

/be

Comment 3

[David Humphrey (:humph)]

Yes, I've been loving Patrick's extension--it's allowed me to get this data.  If there are other tricks he has for me, I'd love to learn more.

I have a build smaug made on try server from bug 624549 that I'll try locally.

Comment 4

[Boris Zbarsky [:bzbarsky]]

David, that's a tiny sample. What sampling interval did you use for Shark?  If it wasn't the minimal 20us, can you try again with that?

In any case, what that profile (which may or may not be representative) does show is that we end up with some sort of presumably-huge table in the cycle collector that we hit a lot...  And most of the things in it are there because they're sitting in an array somewhere.  Got any large arrays of objects around?

Comment 5

[David Humphrey (:humph)]

The demo is a 6-minute WebGL music video sort of, and we have tons of geometry in arrays, yes.

I can get other samples for you with longer intervals.

This may not be connected here, but Benoit and I also observed this with a recent trunk build + bug 601949, which instruments js_GC:

thinking:mozilla-central-clean dave$ There have been 66 GC runs.
1 GC runs took between 4.10e-03 and 8.19e-03 seconds
1 GC runs took between 8.19e-03 and 1.64e-02 seconds
0 GC runs took between 1.64e-02 and 3.28e-02 seconds
4 GC runs took between 3.28e-02 and 6.55e-02 seconds
17 GC runs took between 6.55e-02 and 1.31e-01 seconds
24 GC runs took between 1.31e-01 and 2.62e-01 seconds
18 GC runs took between 2.62e-01 and 5.24e-01 seconds
1 GC runs took between 5.24e-01 and 1.05e+00 seconds
Minimum duration of a GC run: 4.525e-03 seconds
Average duration of a GC run: 2.032e-01 seconds
Maximum duration of a GC run: 6.341e-01 seconds

Comment 6

[Andreas Gal :gal]

David, if you guys can record a profile for me I can check whats taking so long there (during the GC run).

Comment 7

[David Humphrey (:humph)]

Here's another profile, this time going ~20 seconds (or whatever Shark's default period is):

http://scotland.proximity.on.ca/dxr/tmp/audio-demo2.mshark

Comment 8

[David Humphrey (:humph)]

We're also seeing a ton of DrawElements in all the profiles I'm taking (some as high as 10%).  Not related to the CC stuff, but listing here to keep track of it with respect to this demo (see bug 569431).

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

So is this about CC or GC?

Comment 10

[David Humphrey (:humph)]

Attachment: Comparison of trunk run (top) vs build from bug 624549 (bottom)

bz: I've reposted the mshark file (http://scotland.proximity.on.ca/dxr/tmp/audio-demo2.mshark) in the hopes that it was corrupted in transport (it works here).

Last night we did a dozen or so runs with various browsers and tweaks to our code.  The performance of the demo is basically the same in every case, though it does run better with the build from bug 624549.  I've posted a screenshot of the two fps graphs using Patrick's addon, and you can easily see where we get the pauses (trunk is on the top, smaug's modified build on the bottom).

"Is this gc or cc" -- I don't pretend to understand enough of either to say with certainty, but I think it's both.  Yesterday when we were profiling with Benoit and Jeff, we saw a lot of the Cycle Collector on the shark profiles, but Benoit also got lots of GC pauses with his patch.

I think we are going to try and get a copy of this put somewhere that we can point people in the bug toward.  The deadline for this is ahead of the ff4 end-date.

Comment 11

[Peter Van der Beken [:peterv]]

(In reply to comment #7)
> Here's another profile, this time going ~20 seconds

20000 samples for 20 seconds means an interval of 1ms. Like bz said, please use 20μs.

Looks like a lot of time is spent traversing JS arrays/objects. We'll need to know more about the testcase, for example where these arrays/objects are stored.

Comment 12

[David Humphrey (:humph)]

I wanted to say thanks to Benoit and Olli, who have both spent a lot of time fixing 3 bad performance bugs affecting this between them.  I'm going to close this based on those landings.  Fantastic work.  We appreciate it.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

I hope we could still tweak GC handling for FF4.