744546 - lots of animation stalls in NoComply gamelet; speculatively caused by TI info being thrown out on GC

Status: RESOLVED INVALID

(Core :: JavaScript Engine, defect)

Description

[Dan Mosedale (:dmosedale, :dmose)]

In the NoComply gamelet that's in progress as part of the Gladius game engine project, on OS X Lion, running and jumping the character around the main screen causes lots of animation stalls in nightly, and almost none in release builds of Chrome.

After poking at this briefly with azakai and pcwalton using the error console and about:jank, it was speculated that this could be caused by the type-inference info being thrown out on every full GC, forcing it to be recompiled.

about:jank output after running around in the game doesn't show an interesting time being spent in GC itself or even rendering, thus the theory that the TI lossage could be the problem:

4123 - c-Timer::Fire
604 - c-LayerManagerOGL::Render
243 - c-Events::ProcessGeckoEvents
100 - c-nsEventListenerManager::HandleEventInternal
50 - c-Paint::PresShell::Paint
40 - c-JS::CallEventHandler
32 - c-JS::EvaluateString
25 - c-gfx::DrawThebesLayer
22 - c-CC::nsCycleCollector_collect
13 - c-event::nsViewManager::DispatchEvent
11 - c-GLContext::SwapBuffers
11 - c-layout::DoReflow
10 - c-CC::nsCycleCollector_forgetSkippable
10 - c-layout::FlushPendingNotifications
6 - c-network::nsHttpChannel::OnDataAvailable
3 - c-CSS::ProcessRestyles
1 - c-network::nsStreamLoader::OnStopRequest

Some notes: the game itself and the Gladius engine haven't been profiled or optimized really at all, so we're almost certainly doing a bunch of bad stuff in the JS itself.  However, since this exact naively-written code runs so much more smoothly on Chrome, there would seem to be something unfortunate going on at the platform-level as well.

To get ahold of the code, execute

git clone --recursive git://github.com/gladiusjs/gladius-core.git

and then point your browser through a webserver (file: won't work) at 

gladius-core/example/no-comply/

Let us know if there are things we can do to help diagnose further...

Comment 2

[Dan Mosedale (:dmosedale, :dmose)]

Somehow there ended up being two bugs here.  I've DUPed the other to this one.  There, Luke wrote:

> Bill has a tool for visualizing what happens on each frame which would confirm
> whether this was caused by recompilation.

Comment 3

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

Someone who works in the Toronto office should get Benoit Girard (:BenWa) to give you a little built-in-profiler tutorial. Especially since you're on OSX where it already works well.

Failing that, the most useful thing is probably to profile this with Shark.

Comment 4

[Dan Mosedale (:dmosedale, :dmose)]

After poking around, I found more info about Bill M's GC visualization tool in bug 684072.

Comment 5

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

Yeah, I just ran it under the tool and the slow frames are caused by recompilation.

On my machine, to render a typical frame we spend ~35ms in JS code (compared to ~20ms painting). When a GC happens, it takes ~23ms, which by itself isn't really noticeable. But then the next frame spends ~286ms in JS code, which is partly the cost of recompiling and partly the time we spend in the interpreter before compiling. The frames after that takes 107ms, 50ms, and 46ms, for similar reasons. After a few more frames, the time goes back down to ~35ms.

Comment 6

[David Mandelin [:dmandelin]]

For now, tracking the possible solution instead.

Comment 7

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Is this still an issue now that bug 750834 has landed?

Comment 8

[Dan Mosedale (:dmosedale, :dmose)]

Things are much better now; I need to find a few minutes to go run comparisons between Chrome and Fx Nightlies as well as look at more about:jank output before closing this out/verifying it.

Comment 9

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Ping -- any updates?