Last Comment Bug 754303 - Periodic extended GC pauses when running Coppercube Backyard WebGL demo
: Periodic extended GC pauses when running Coppercube Backyard WebGL demo
Status: RESOLVED FIXED
[js:p2]
:
Product: Core
Classification: Components
Component: Canvas: WebGL (show other bugs)
: Trunk
: All All
: -- normal (vote)
: mozilla15
Assigned To: Benoit Jacob [:bjacob] (mostly away)
:
Mentors:
Depends on: 743112
Blocks:
  Show dependency treegraph
 
Reported: 2012-05-11 08:38 PDT by Christian Sonne [:cers]
Modified: 2012-06-01 12:58 PDT (History)
8 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
fixed
fixed


Attachments
WebGLUniformLocation doesn't need to be a WebGLRefCountedObject, i.e. all that work we're doing here is useless (3.20 KB, patch)
2012-05-22 12:15 PDT, Benoit Jacob [:bjacob] (mostly away)
no flags Details | Diff | Review
WebGLUniformLocation doesn't need to be a WebGLRefCountedObject, i.e. all that work we're doing here is useless (3.76 KB, patch)
2012-05-22 12:18 PDT, Benoit Jacob [:bjacob] (mostly away)
jmuizelaar: review+
akeybl: approval‑mozilla‑aurora+
Details | Diff | Review

Description Christian Sonne [:cers] 2012-05-11 08:38:17 PDT
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 (PTO-ish through 6-29) [:mccr8] 2012-05-11 10:19:21 PDT
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 (:billm) 2012-05-11 10:27:28 PDT
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 (PTO-ish through 6-29) [:mccr8] 2012-05-11 11:01:46 PDT
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) 2012-05-22 11:23:23 PDT
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 (:billm) 2012-05-22 11:33:55 PDT
Thanks, Vladan. This looks like a WebGL problem.
Comment 6 Benoit Jacob [:bjacob] (mostly away) 2012-05-22 12:15:53 PDT
Created attachment 626124 [details] [diff] [review]
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) 2012-05-22 12:18:38 PDT
Created attachment 626126 [details] [diff] [review]
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) 2012-05-23 09:22:38 PDT
http://hg.mozilla.org/integration/mozilla-inbound/rev/5f14275bb276
Comment 9 Benoit Jacob [:bjacob] (mostly away) 2012-05-23 09:25:22 PDT
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] 2012-05-24 10:53:37 PDT
https://hg.mozilla.org/mozilla-central/rev/5f14275bb276
Comment 11 Benoit Jacob [:bjacob] (mostly away) 2012-05-24 15:01:04 PDT
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] 2012-05-29 10:50:32 PDT
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) 2012-06-01 12:58:26 PDT
http://hg.mozilla.org/releases/mozilla-aurora/rev/feacec1c8195

Note You need to log in before you can comment on or make changes to this bug.