What causes a function to be "optimized too many times"? How do I avoid it?

[Kevin Gadd]

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

[Vyacheslav Egorov]

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

> --
> v8-users mailing list
> v8-u...@googlegroups.com
> http://groups.google.com/group/v8-users

[Kevin Gadd]

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

--
-kg

[Vyacheslav Egorov]

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

[Sven Panne]

On Wed, Nov 7, 2012 at 6:29 PM, Vyacheslav Egorov <veg...@chromium.org> wrote:

[...] Sven recently was changing things in that neighborhood. I am CCing

him. I hope he will be able to help.

I am not sure which neighborhood we are talking about, but I'll take a look... ;-)

[Kevin Gadd]

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

[Vyacheslav Egorov]

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