754303 - Periodic extended GC pauses when running Coppercube Backyard WebGL demo

Status: RESOLVED FIXED

(Core :: Graphics: CanvasWebGL, defect)

Description

[Christian Sonne [:cers]]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:15.0) Gecko/15.0 Firefox/15.0a1
Build ID: 20120510145529

Steps to reproduce:

1) Go to http://www.ambiera.com/coppercube/demo.php?demo=backyard&mode=webgl
2) Click "Click here to start loading the demo"


Actual results:

After the demo has loaded, it runs smoothly but is regularly interrupted for extended periods by GC. It appears to be 2-5s pauses every 4-5s (that is, 4-5s after last pause)


Expected results:

Demo should run smoothly (or at least at a stable speed)

Comment 1

[Andrew McCreight [:mccr8]]

I still get huge GC pauses on this, even with incremental GC enabled (though this is with a few other tabs open).  Almost all of the time is in "end callback", whatever that is. (I tried it on OSX.)

GC(T+3355.4) Total Time: 4166.2ms, Compartments Collected: 1, Total Compartments: 370, MMU (20ms): 0%, MMU (50ms): 0%, Max Pause: 4122.6ms, Allocated: 217MB, +Chunks: 3, -Chunks: 0
    Slice: 0, Pause: 26.0 (When: 26.0ms, Reason: MAYBEGC): Mark: 22.9ms, Mark Roots: 12.9ms, Discard Code: 2.7ms
    Slice: 3, Pause: 4122.6 (When: 4272.3ms, Reason: REFRESH_FRAME): Mark: 1.0ms, Mark Other: 0.5ms, Finalize Start Callback: 0.4ms, Sweep: 173.6ms, Sweep Compartments: 7.5ms, Sweep Object: 158.7ms, Discard Code: 1.5ms, Discard Analysis: 6.0ms, Discard TI: 0.2ms, Sweep Types: 0.1ms, Finalize End Callback: 2.6ms, End Callback: 3948.2ms
    Totals: Mark: 41.1ms, Mark Roots: 12.9ms, Mark Other: 0.5ms, Finalize Start Callback: 0.4ms, Sweep: 173.6ms, Sweep Compartments: 7.5ms, Sweep Object: 158.7ms, Discard Code: 4.2ms, Discard Analysis: 6.0ms, Discard TI: 0.2ms, Sweep Types: 0.1ms, Finalize End Callback: 2.6ms, End Callback: 3948.2ms

GC(T+3344.7) Total Time: 2516.5ms, Compartments Collected: 1, Total Compartments: 364, MMU (20ms): 0%, MMU (50ms): 0%, Max Pause: 2472.7ms, Allocated: 213MB, +Chunks: 21, -Chunks: 143
    Slice: 0, Pause: 26.8 (When: 26.8ms, Reason: MAYBEGC): Mark: 24.3ms, Mark Roots: 14.3ms, Discard Code: 2.1ms
    Slice: 3, Pause: 2472.7 (When: 2667.9ms, Reason: REFRESH_FRAME): Mark: 5.5ms, Mark Other: 2.7ms, Finalize Start Callback: 0.4ms, Sweep: 136.2ms, Sweep Compartments: 7.4ms, Sweep Object: 121.5ms, Discard Code: 1.0ms, Discard Analysis: 6.3ms, Discard TI: 0.2ms, Sweep Types: 0.1ms, Finalize End Callback: 2.6ms, End Callback: 2333.3ms
    Totals: Mark: 46.4ms, Mark Roots: 14.3ms, Mark Delayed: 0.2ms, Mark Other: 2.7ms, Finalize Start Callback: 0.4ms, Sweep: 136.2ms, Sweep Compartments: 7.4ms, Sweep Object: 121.5ms, Discard Code: 3.2ms, Discard Analysis: 6.3ms, Discard TI: 0.2ms, Sweep Types: 0.1ms, Finalize End Callback: 2.6ms, End Callback: 2333.3ms

Comment 2

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

The "End Callback" is responsible for doing the deferred release of C++ refcounted objects. So we have a bunch of wrapped natives or something, and they all get collected, and we end up running a lot of C++ destructors, which takes a while.

Bug 743112 was designed to help here. I need to get back to it--it was pretty orange the last time I worked on it. However, we should probably try to understand why we're doing so much releasing. Is it because there are tons of objects, or is it a few objects that are very slow to be destroyed? Given how little time we spend in the mark and sweep phases, it seems likely to be the latter. It might not be a bad idea to profile this thing and see if any destructors show up.

Comment 3

[Andrew McCreight [:mccr8]]

CC times didn't seem that bad, so I would guess that there aren't a huge number of wrapped natives.

Comment 4

[Vladan Djeric (:vladan)]

I used a profiling build and the new chrome hang functionality to get call stacks from the hangs lasting more than a second. They all look the same:

??? (in MSVCR100.dll)
nsTArray_base::ShiftData(unsigned int,unsigned int,unsigned int,unsigned int,unsigned int) (in xul.dll)
nsTArray::Entry,nsTArrayDefaultAllocator>::RemoveElementsAt(unsigned int,unsigned int) (in xul.dll)
nsTArray::Entry,nsTArrayDefaultAllocator>::RemoveElementAt(unsigned int) (in xul.dll)
nsTArray::Entry,nsTArrayDefaultAllocator>::RemoveElementSorted::Entry,mozilla::WebGLFastArray::Entry::Comparator>(mozilla::WebGLFastArray::Entry const &,mozilla::WebGLFastArray::Entry::Comparator const &) (in xul.dll)
mozilla::WebGLFastArray::RemoveElement(unsigned __int64) (in xul.dll)
mozilla::WebGLUniformLocation::Delete() (in xul.dll)
mozilla::WebGLRefCountedObject::DeleteOnce() (in xul.dll)
mozilla::WebGLUniformLocation::~WebGLUniformLocation() (in xul.dll)
mozilla::WebGLUniformLocation::`scalar deleting destructor'(unsigned int) (in xul.dll)
mozilla::WebGLUniformLocation::Release() (in xul.dll)
DoDeferredRelease (in xul.dll)
XPCJSRuntime::GCCallback(JSRuntime *,JSGCStatus) (in xul.dll)
Collect (in mozjs.dll)
js::GCSlice(JSRuntime *,js::JSGCInvocationKind,js::gcreason::Reason) (in mozjs.dll)
js::MaybeGC(JSContext *) (in mozjs.dll)
nsJSContext::ScriptEvaluated(bool) (in xul.dll)
nsCxPusher::Pop() (in xul.dll)
nsJSContext::CallEventHandler(nsISupports *,JSObject *,JSObject *,nsIArray *,nsIVariant * *) (in xul.dll)
nsGlobalWindow::RunTimeout(nsTimeout *) (in xul.dll)
nsGlobalWindow::TimerCallback(nsITimer *,void *) (in xul.dll)
nsTimerImpl::Fire() (in xul.dll)
nsTimerEvent::Run() (in xul.dll)
nsThread::ProcessNextEvent(bool,bool *) (in xul.dll)
mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) (in xul.dll)
MessageLoop::RunHandler() (in xul.dll)
MessageLoop::Run() (in xul.dll)
nsBaseAppShell::Run() (in xul.dll)
nsAppShell::Run() (in xul.dll)
nsAppStartup::Run() (in xul.dll)
XREMain::XRE_mainRun() (in xul.dll)
XREMain::XRE_main(int,char * * const,nsXREAppData const *) (in xul.dll)
XRE_main (in xul.dll)
wmain (in firefox.exe)
__tmainCRTStartup (in firefox.exe)
??? (in kernel32.dll)
??? (in ntdll.dll)
??? (in ntdll.dll)

Comment 5

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Thanks, Vladan. This looks like a WebGL problem.

Comment 6

[Benoit Jacob [:bjacob] (mostly away)]

Attachment: WebGLUniformLocation doesn't need to be a WebGLRefCountedObject, i.e. all that work we're doing here is useless

WebGLUniformLocation objects can't be kept alive by the WebGL context or by other WebGL objects. So all the bookkeeping we're doing here, is not needed. Removing.

Comment 7

[Benoit Jacob [:bjacob] (mostly away)]

Attachment: WebGLUniformLocation doesn't need to be a WebGLRefCountedObject, i.e. all that work we're doing here is useless

Removed mMonotonicHandle as well.

Comment 8

[Benoit Jacob [:bjacob] (mostly away)]

http://hg.mozilla.org/integration/mozilla-inbound/rev/5f14275bb276

Comment 9

[Benoit Jacob [:bjacob] (mostly away)]

Comment on attachment 626126 [details] [diff] [review]
WebGLUniformLocation doesn't need to be a WebGLRefCountedObject, i.e. all that work we're doing here is useless

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 707033
User impact if declined: Performance issue: Long GC pauses during certain WebGL animations (not all WebGL animations, just those that create a zillion WebGLUniformLocation's)
Testing completed (on m-c, etc.): m-i
Risk to taking this patch (and alternatives if risky): not risky at all. Just removal of useless code.
String or UUID changes made by this patch: none

Comment 10

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/5f14275bb276

Comment 11

[Benoit Jacob [:bjacob] (mostly away)]

Filed Bug 758404 about getting rid of the remaining arrays, in favor of MFBT LinkedList, for other WebGL object types. Has patch.

Comment 12

[Alex Keybl [:akeybl]]

Comment on attachment 626126 [details] [diff] [review]
WebGLUniformLocation doesn't need to be a WebGLRefCountedObject, i.e. all that work we're doing here is useless

[Triage Comment]
Low risk perf fix. Approved for Aurora 14.

Comment 13

[Benoit Jacob [:bjacob] (mostly away)]

http://hg.mozilla.org/releases/mozilla-aurora/rev/feacec1c8195