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.
**** DEOPT: DrawScaleF at bailout #19, address 0x0, frame size 40
;;; @292: check-prototype-maps.
[deoptimizing: begin 0x51b14d05 DrawScaleF @19]
translating DrawScaleF => node=190, height=76
0xbff70d18: [top + 128] <- 0x585febd1 ; [sp + 92] 0x585febd1 <a
Microsoft_Xna_Framework_Graphics_SpriteBatch>
0xbff70d14: [top + 124] <- 0x24ed70d1 ; [sp + 88] 0x24ed70d1 <an
HTML5ImageAsset>
0xbff70d10: [top + 120] <- 0x4e4b96d9 ; [sp + 84] 0x4e4b96d9 <an Object>
0xbff70d0c: [top + 116] <- 0x4e4e07d5 ; [sp + 80] 0x4e4e07d5 <a
Microsoft_Xna_Framework_Rectangle>
0xbff70d08: [top + 112] <- 0x4e4cd1ed ; [sp + 76] 0x4e4cd1ed <a
Microsoft_Xna_Framework_Color>
0xbff70d04: [top + 108] <- 0x00000000 ; [sp + 72] 0
0xbff70d00: [top + 104] <- 0x462f1199 ; [sp + 68] 0x462f1199 <a
Microsoft_Xna_Framework_Vector2>
0xbff70cfc: [top + 100] <- 0x00000002 ; [sp + 64] 1
0xbff70cf8: [top + 96] <- 0x449a2edd ; [sp + 60] 0x449a2edd <a
Microsoft_Xna_Framework_Graphics_SpriteEffects>
0xbff70cf4: [top + 92] <- 0x47b2609d ; [sp + 56] 0x47b2609d
<Number: 0.1290322580645161>
0xbff70cf0: [top + 88] <- 0x223b0d4b ; caller's pc
0xbff70cec: [top + 84] <- 0xbff70d28 ; caller's fp
0xbff70ce8: [top + 80] <- 0x51b12e11 ; context
0xbff70ce4: [top + 76] <- 0x51b14d05 ; function
0xbff70ce0: [top + 72] <- 0x000000a0 ; [sp + 28] 80
0xbff70cdc: [top + 68] <- 0x00000040 ; [sp + 20] 32
0xbff70cd8: [top + 64] <- 0x00000020 ; [sp + 24] 16
0xbff70cd4: [top + 60] <- 0x00000020 ; [sp + 12] 16
0xbff70cd0: [top + 56] <- 0x51b14d05 ; [sp + 16] 0x51b14d05 <JS
Function DrawScaleF>
0xbff70ccc: [top + 52] <- 0x585febd1 ; [sp + 92] 0x585febd1 <a
Microsoft_Xna_Framework_Graphics_SpriteBatch>
0xbff70cc8: [top + 48] <- 0x24ed70d1 ; [sp + 88] 0x24ed70d1 <an
HTML5ImageAsset>
0xbff70cc4: [top + 44] <- 0x000002f0 ; [sp + 8] 376
0xbff70cc0: [top + 40] <- 0x00000010 ; [sp + 4] 8
0xbff70cbc: [top + 36] <- 0x00000020 ; [sp + 24] 16
0xbff70cb8: [top + 32] <- 0x00000020 ; [sp + 12] 16
0xbff70cb4: [top + 28] <- 0x000000a0 ; [sp + 28] 80
0xbff70cb0: [top + 24] <- 0x00000040 ; [sp + 20] 32
0xbff70cac: [top + 20] <- 0x00000020 ; [sp + 24] 16
0xbff70ca8: [top + 16] <- 0x00000020 ; [sp + 12] 16
0xbff70ca4: [top + 12] <- 0x4e4cd1ed ; [sp + 76] 0x4e4cd1ed <a
Microsoft_Xna_Framework_Color>
0xbff70ca0: [top + 8] <- 0x00000000 ; [sp + 72] 0
0xbff70c9c: [top + 4] <- 0x00000010 ; [sp + 0] 8
0xbff70c98: [top + 0] <- 0x00000010 ; eax 8
[deoptimizing: end 0x51b14d05 DrawScaleF => node=190, pc=0x497cac9d,
state=NO_REGISTERS, alignment=no padding, took 0.060 ms]
[removing optimized code for: DrawScaleF]
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 <[email protected]> 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 <[email protected]>
> 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 <[email protected]> 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).
>> >
>> > 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
>>
>> --
>> v8-users mailing list
>> [email protected]
>> http://groups.google.com/group/v8-users
>
>
>
>
> --
> -kg
>
> --
> v8-users mailing list
> [email protected]
> http://groups.google.com/group/v8-users
--
v8-users mailing list
[email protected]
http://groups.google.com/group/v8-users
