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 <[email protected]>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.
>
> **** 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
>
--
-kg
--
v8-users mailing list
[email protected]
http://groups.google.com/group/v8-users
