Hi,
I've been looking into some performance issues in Chrome Canary for a HTML5
game I released a little while back. At present, Firefox Nightly runs this
game a lot faster than Canary does, which is surprising to me because
Chrome has a much better Canvas backend and used to do much better at
running this game. From doing some profiling and comparing profiles between
the browsers, I am pretty sure I am running into a V8 issue here - perhaps
because something is wrong with my JS.
I ran the game with trace-opt, trace-bailout and trace-deopt turned on. I
see tons and tons of marking and optimization happening while the game is
running, and it never settles down, despite the fact that the game is not
particularly dynamic once it gets going - it reaches a steady state where
it is not generating tons of code on the fly, and types are not changing,
so it shouldn't be necessary to constantly recompile functions.
Worse, though, I see a lot of these messages:
[disabled optimization for Game_EnqueueTick, reason: optimized too many
times]
[disabled optimization for KinematicBody_get_SupportingBody, reason:
optimized too many times]
[disabled optimization for SpriteBatch_InternalDraw, reason: optimized too
many times]
[disabled optimization for DrawScaleF, reason: optimized too many times]
[disabled optimization for SpriteBatch_DeferBlit, reason: optimized too
many times]
>From looking at the code, this appears to be a deopt that is hit once a
function has been optimized 1000 times. I can't imagine why these functions
would be optimized 1000 times in the first place, and the deopt seems to be
hurting them because profiles in the Web Inspector show some of these
functions as bottlenecks - but in SpiderMonkey they barely contribute to
CPU time in comparison (and some of them are extremely simple).
For example:
function DrawScaleF (texture, position, sourceRectangle, color,
rotation, origin, scale, effects, layerDepth) {
var sourceX = 0, sourceY = 0, sourceWidth = 0, sourceHeight = 0;
if (sourceRectangle !== null) {
sourceX = sourceRectangle.X;
sourceY = sourceRectangle.Y;
sourceWidth = sourceRectangle.Width;
sourceHeight = sourceRectangle.Height;
} else {
sourceWidth = texture.Width;
sourceHeight = texture.Height;
}
this.InternalDraw(
texture, position.X, position.Y, sourceWidth, sourceHeight,
sourceX, sourceY, sourceWidth, sourceHeight,
color, rotation,
origin.X, origin.Y,
scale, scale,
effects, layerDepth
);
}
This function is pretty simple, and the type information should basically
never change. sourceRectangle is always either null or an instance of one
specific class, texture is always an instance of one specific class, etc.
The function isn't doing any arithmetic or calling complex functions, it's
basically just a wrapper around InternalDraw.
Normally I would expect this function to entirely get optimized out, or at
least get reduced down to some really simple code. That appears to be what
happens in SpiderMonkey.
So, for stuff like this, what steps should I take to understand why a
function is being recompiled lots of times, and how can I work around this?
If I manage to get the hydrogen IR dumped, can I look for particular
warning signs in the IR for these functions? Are there some other debug
flags I can pass to the runtime to get diagnostic information here?
If you want to test the game yourself with flags set, it's at
http://www.playescapegoat.com/. Just playing one or two stages should be
enough to generate lots of those messages.
Possibly related: In the logs, sometimes I see it reoptimize the same
function like ten times back to back. Is this right? It seems like it
shouldn't happen.
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 1.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[optimizing: DrawScaleF / 2c69a039 - took 0.000, 0.000, 0.000 ms]
[marking DrawScaleF 0x2c69a038 for recompilation, reason: small function,
ICs with typeinfo: 11/11 (100%)]
[disabled optimization for DrawScaleF, reason: optimized too many times]
I've uploaded a log of one run with the trace options set here, if you want
to look at it:
http://pastebin.com/7aCyeZC2
You can see some of the stuff I describe.
Thanks,
-kg
--
v8-users mailing list
[email protected]
http://groups.google.com/group/v8-users
