Figuring out which value requires looking at the IR dumped with --trace-hydrogen.
As for logs: on Windows you can patch your chrome.exe as I describe here: http://mrale.ph/blog/2012/06/21/v8s-flags-and-chrome-on-windows.html and then a simple unix style redirection works from command prompt: chrome.exe --no-sandbox --js-flags="--trace-opt --trace-deopt" > log.txt Vyacheslav Egorov On Thu, Nov 8, 2012 at 4:48 AM, Kevin Gadd <[email protected]> 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 <[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 -- v8-users mailing list [email protected] http://groups.google.com/group/v8-users
