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).
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.
On Tue, Nov 6, 2012 at 12:33 AM, Kevin Gadd <kevin.g...@gmail.com> wrote:
> 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).
> 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.
Yeah, as I said I ran with trace-opt, trace-bailout and trace-deopt turned
on. So 'disabled optimization for' doesn't mean the function is
deoptimized? That's really surprising to me, because I see a performance
hit for those functions, and I assume that optimization being turned off
would mean that the functions would have to run using unoptimized JIT
output. That's not the case then? Does that mean that this error message
doesn't matter, and it's intended that these functions keep getting
recompiled until they hit the limit?
It would be cool to know how to find out why the functions keep getting
marked for recompilation, since the compiles seem to be taking time, but I
guess that's less of an issue.
Thanks,
-kg
On Tue, Nov 6, 2012 at 8:04 AM, Vyacheslav Egorov <vego...@chromium.org>wrote:
> I do not see any deoptimizations in the log you have attached, were
> you running with --trace-deopt?
> Vyacheslav Egorov
> On Tue, Nov 6, 2012 at 12:33 AM, Kevin Gadd <kevin.g...@gmail.com> wrote:
> > 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).
> > 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.
I do not see such deopt on Chrome 23 (though I did see some deopts of
this function). This indeed looks like an issue either with type
feedback or with generated code, though I can't be sure.
Sven recently was changing things in that neighborhood. I am CCing
him. I hope he will be able to help.
Vyacheslav Egorov
On Tue, Nov 6, 2012 at 4:16 PM, Kevin Gadd <kevin.g...@gmail.com> wrote:
> Hi Vyacheslav,
> Yeah, as I said I ran with trace-opt, trace-bailout and trace-deopt turned
> on. So 'disabled optimization for' doesn't mean the function is deoptimized?
> That's really surprising to me, because I see a performance hit for those
> functions, and I assume that optimization being turned off would mean that
> the functions would have to run using unoptimized JIT output. That's not the
> case then? Does that mean that this error message doesn't matter, and it's
> intended that these functions keep getting recompiled until they hit the
> limit?
> It would be cool to know how to find out why the functions keep getting
> marked for recompilation, since the compiles seem to be taking time, but I
> guess that's less of an issue.
> Thanks,
> -kg
> On Tue, Nov 6, 2012 at 8:04 AM, Vyacheslav Egorov <vego...@chromium.org>
> wrote:
>> Hi Kevin,
>> Does it deoptimize?
>> I do not see any deoptimizations in the log you have attached, were
>> you running with --trace-deopt?
>> Vyacheslav Egorov
>> On Tue, Nov 6, 2012 at 12:33 AM, Kevin Gadd <kevin.g...@gmail.com> wrote:
>> > 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).
>> > 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
Interesting, I wonder why --trace-deopt isn't spitting out deopt notices
for me. Maybe some of the output is being lost because I'm using WinDbg to
capture it. I used to get deopt output there, though...
Is there a way to tell which value is causing check-prototype-maps to fail?
Is it a check performed on the this-reference?
Thanks for taking a look, I appreciate it. I did some more testing using
the release version of chrome and at present most JSIL code seems to
perform dramatically better there - I'm seeing 4-5x performance regressions
for some simple hot functions in Canary, like this one for example (source
from a local build - haven't uploaded it to production yet because I'm wary
of making things worse):
function KinematicBody_get_DynamicAreaSubPx () {
var areaPosition = this._area.get_PositionSubPx();
var x = ((areaPosition.X - this.HalfWidthSubPx) | 0);
var y = ((areaPosition.Y - this.HalfHeightSubPx) | 0);
var w = ((this.HalfWidthSubPx * 2) | 0);
var h = ((this.HalfHeightSubPx * 2) | 0);
if (!((this._DynamicAreaSubPx.X === x) &&
(this._DynamicAreaSubPx.Y === y) &&
(this._DynamicAreaSubPx.Width === w) &&
(this._DynamicAreaSubPx.Height === h))) {
this._DynamicAreaSubPx = new ($T15())(x, y, w, h);
}
return this._DynamicAreaSubPx;
}
In that function all the direct property accesses aren't going through
getter/setter functions, so there shouldn't be very much actually happening
in there. This seems to be supported by it performing fine in release
branch Chrome. It makes me wonder if some particular pattern in my
generated code is causing newer revisions of V8 some grief (lazy
initialization, perhaps?)
Sven, let me know if I can provide you additional details (or chrome
traces, or whatever) to help you investigate this.
Thanks,
-kg
On Wed, Nov 7, 2012 at 9:29 AM, Vyacheslav Egorov <vego...@chromium.org>wrote:
> I do not see such deopt on Chrome 23 (though I did see some deopts of
> this function). This indeed looks like an issue either with type
> feedback or with generated code, though I can't be sure.
> Sven recently was changing things in that neighborhood. I am CCing
> him. I hope he will be able to help.
> Vyacheslav Egorov
> On Tue, Nov 6, 2012 at 4:16 PM, Kevin Gadd <kevin.g...@gmail.com> wrote:
> > Hi Vyacheslav,
> > Yeah, as I said I ran with trace-opt, trace-bailout and trace-deopt
> turned
> > on. So 'disabled optimization for' doesn't mean the function is
> deoptimized?
> > That's really surprising to me, because I see a performance hit for those
> > functions, and I assume that optimization being turned off would mean
> that
> > the functions would have to run using unoptimized JIT output. That's not
> the
> > case then? Does that mean that this error message doesn't matter, and
> it's
> > intended that these functions keep getting recompiled until they hit the
> > limit?
> > It would be cool to know how to find out why the functions keep getting
> > marked for recompilation, since the compiles seem to be taking time, but
> I
> > guess that's less of an issue.
> > Thanks,
> > -kg
> > On Tue, Nov 6, 2012 at 8:04 AM, Vyacheslav Egorov <vego...@chromium.org>
> > wrote:
> >> Hi Kevin,
> >> Does it deoptimize?
> >> I do not see any deoptimizations in the log you have attached, were
> >> you running with --trace-deopt?
> >> Vyacheslav Egorov
> >> On Tue, Nov 6, 2012 at 12:33 AM, Kevin Gadd <kevin.g...@gmail.com>
> wrote:
> >> > 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).
On Thu, Nov 8, 2012 at 4:48 AM, Kevin Gadd <kevin.g...@gmail.com> wrote:
> Interesting, I wonder why --trace-deopt isn't spitting out deopt notices for
> me. Maybe some of the output is being lost because I'm using WinDbg to
> capture it. I used to get deopt output there, though...
> Is there a way to tell which value is causing check-prototype-maps to fail?
> Is it a check performed on the this-reference?
> Thanks for taking a look, I appreciate it. I did some more testing using the
> release version of chrome and at present most JSIL code seems to perform
> dramatically better there - I'm seeing 4-5x performance regressions for some
> simple hot functions in Canary, like this one for example (source from a
> local build - haven't uploaded it to production yet because I'm wary of
> making things worse):
> function KinematicBody_get_DynamicAreaSubPx () {
> var areaPosition = this._area.get_PositionSubPx();
> var x = ((areaPosition.X - this.HalfWidthSubPx) | 0);
> var y = ((areaPosition.Y - this.HalfHeightSubPx) | 0);
> var w = ((this.HalfWidthSubPx * 2) | 0);
> var h = ((this.HalfHeightSubPx * 2) | 0);
> if (!((this._DynamicAreaSubPx.X === x) &&
> (this._DynamicAreaSubPx.Y === y) &&
> (this._DynamicAreaSubPx.Width === w) &&
> (this._DynamicAreaSubPx.Height === h))) {
> this._DynamicAreaSubPx = new ($T15())(x, y, w, h);
> }
> return this._DynamicAreaSubPx;
> }
> In that function all the direct property accesses aren't going through
> getter/setter functions, so there shouldn't be very much actually happening
> in there. This seems to be supported by it performing fine in release branch
> Chrome. It makes me wonder if some particular pattern in my generated code
> is causing newer revisions of V8 some grief (lazy initialization, perhaps?)
> Sven, let me know if I can provide you additional details (or chrome traces,
> or whatever) to help you investigate this.
> Thanks,
> -kg
> On Wed, Nov 7, 2012 at 9:29 AM, Vyacheslav Egorov <vego...@chromium.org>
> wrote:
>> I asked because it is highly unlikely that any big application runs
>> without deopts.
>> I just tried to run the game in Chrome Canary on Mac with
>> --js-flags="--trace-deopt --code-comments" and I saw many deopts.
>> DrawScaleF constantly deopts on check-prototype-maps.
>> I do not see such deopt on Chrome 23 (though I did see some deopts of
>> this function). This indeed looks like an issue either with type
>> feedback or with generated code, though I can't be sure.
>> Sven recently was changing things in that neighborhood. I am CCing
>> him. I hope he will be able to help.
>> Vyacheslav Egorov
>> On Tue, Nov 6, 2012 at 4:16 PM, Kevin Gadd <kevin.g...@gmail.com> wrote:
>> > Hi Vyacheslav,
>> > Yeah, as I said I ran with trace-opt, trace-bailout and trace-deopt
>> > turned
>> > on. So 'disabled optimization for' doesn't mean the function is
>> > deoptimized?
>> > That's really surprising to me, because I see a performance hit for
>> > those
>> > functions, and I assume that optimization being turned off would mean
>> > that
>> > the functions would have to run using unoptimized JIT output. That's not
>> > the
>> > case then? Does that mean that this error message doesn't matter, and
>> > it's
>> > intended that these functions keep getting recompiled until they hit the
>> > limit?
>> > It would be cool to know how to find out why the functions keep getting
>> > marked for recompilation, since the compiles seem to be taking time, but
>> > I
>> > guess that's less of an issue.
>> > Thanks,
>> > -kg
>> > On Tue, Nov 6, 2012 at 8:04 AM, Vyacheslav Egorov <vego...@chromium.org>
>> > wrote:
>> >> Hi Kevin,
>> >> Does it deoptimize?
>> >> I do not see any deoptimizations in the log you have attached, were
>> >> you running with --trace-deopt?
>> >> Vyacheslav Egorov
>> >> On Tue, Nov 6, 2012 at 12:33 AM, Kevin Gadd <kevin.g...@gmail.com>
>> >> wrote:
>> >> > 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).
