firstChild getter test runs 100x slower after first two runs

[jdm]

To reproduce, run ./mach run tests/html/bindings_perf.html and press the measure firstChild getter button three times. The first two times, I consistently see sub-1ns measurements. Subsequently, I see 15-20ns measures. This is completely reproducible for me every time I run Servo.

Testcase source

cc @bzbarsky any ideas what could cause this off the top of your head? The initial measurements are bizarrely fast; the subsequent ones are much more sensible.

[bzbarsky]

Are those times in a clean tree?

At first glance, looks like servo implements enough of the [Pure] annotation stuff to mark the getter as movable, but not eliminatable (that's #10991 and I have no clue why that wasn't done offhand). That means that in a clean tree, with that property marked [Pure], I would expect Ion to loop-hoist the get and the loop to just be timing the counter increment and loop condition. Which is certainly going to be sub-1ns per iteration on modern desktop hardware, and I consistently see that in Gecko on this testcase.

What's harder to explain in that setup is the slowdown. Maybe see what the various Ion debug output looks like when you click that button for the third time? It's possible we're ending up recompiling the function for some reason and screwing it up or something...

[bzbarsky]

Oh, and if the times are with the [Pure] annotation removed, then I have no idea what's going on, sorry.

[jdm]

Yes, those times are a clean tree.

[bzbarsky]

OK, so I think I understand pretty much all the goings on here. The pieces are:

1. Servo's setup of the global object is buggy and marks it as unoptimizable. #13009 fixes that.
2. Servo's setup of the global object is buggy and puts WebIDL stuff on its prototype, not the object itself. This is apparently covered by an existing issue, but I sure can't find it. @jdm, are you sure this is reported? Are there plans to fix it?
3. IonBuilder::addShapeGuard will mark the guard as not movable if any shape guard in the current script failed in the past(!).

OK, so we go to run our function, which has this body:

var n = document.documentElement;
var start = new Date();
var count = 100000000;
for (var i = 0; i < count; i++) {
  var a = n.firstChild;
}
var stop = new Date();
console.log('firstChild getter: ' + ((stop - start) / count * 1e6) + 'ns');

The first time the function runs, we enter the loop, baseline-compile the function, then ion-compile the function. At this point we have not done the console.log bit yet, so the last property defined on the global is named "Date". This is the global shape that gets stored in the baseline IC at the point when we do the console bareword get, afaict. During ion compilation, we loop-hoist the firstChild bit, so the loop is fast. When we do the console get the shape of the window changes, because a "Console" property is added to it.

The second time the function runs, we ion-compile the function again, find the nice baseline IC for the console get, and output a fast path for it. We add a guard on the global's shape, due to item 2 in our list of fails above; see IonBuilder::testCommonGetterSetter the guardGlobal block. This uses the shape in the baseline IC, which is not the current shape of the global (filed https://bugzilla.mozilla.org/show_bug.cgi?id=1297603 on that). Then we proceed to run the loop. This is still fast, because this compilation also loop-hoists the firstChild bit. But when we get to the shape guard on the console get, we bail out with a shape guard failure.

The third time we run the loop, we recompile it again (presumably due to the earlier bailout from the shape guard). This time we have failed a shape guard in the past, so the shape guard on n inside the loop is marked not movable per item 3 in our list of woe. Since the firstChild get depends on that shape guard, it is likewise not movable, so can't be loop-hoisted. Now every loop iteration actually executes the firstChild get, which is a lot slower than just incrementing a counter.

[jdm]

I also have not been able to find an issue covering the global object properties. It's definitely known, since we've discussed it in the past, and we intend to fix it.

[jdm]

Aha, I was remembering #4593, which claims that it was fixed by #8954 but clearly was not.

[bzbarsky]

Note also that "console" should not be a getter call to start with: see #13010

[nox]

Servo's setup of the global object is buggy and puts WebIDL stuff on its prototype, not the object itself. This is apparently covered by an existing issue, but I sure can't find it. @jdm, are you sure this is reported? Are there plans to fix it?

#4593 is taken care of in pending #13030.

[nox]

@bzbarsky Did #13030 fix some slowness?

[nox]

± ./mach run tests/html/bindings_perf.html --release
firstChild getter: 0.33999999999999997ns
firstChild getter: 0.3ns
firstChild getter: 24.27ns
firstChild getter: 24.57ns
firstChild getter: 24.53ns

:(

[bzbarsky]

It did fix some slowness, yes. if you edit tests/html/bindings_perf.html to do a single "console" get sometime before firstChild_getter is called the first time, then everything is happy: we get about 0.3ns times every click.

With the "console" get happening for the first time at the end of the method, we still get a shape change on the global at that point due to window.Console getting defined. To some extent this is a SpiderMonkey problem (that we should get on file, unless we think https://bugzilla.mozilla.org/show_bug.cgi?id=1297603 or https://bugzilla.mozilla.org/show_bug.cgi?id=1297604 covers it, but I'm not sure they do; please let me know if you need me to investigate what's still failing here). For example, if I add this line to the end of the firstChild_getter method:

window.abcde = 7;

then the times I see logged in Gecko are:

firstChild getter: 0.33ns
firstChild getter: 0.28ns
firstChild getter: 13.11ns
firstChild getter: 14.110000000000001ns
firstChild getter: 12.870000000000001ns

That's what we're getting in servo as well, except firstChild is way slower in servo (on the same hardware I get 23-24ns in a servo release build) and it's happening in servo because the "console" get creates and defines window.Console as I said above.

In Gecko, window.Console is not a thing, because console is a namespace, not an interface. But there's still lazy definition of the window.console property. And that does happen when first touching console at the end of this method. Again, I don't know offhand why this does not cause the same sort of issue in Gecko. Please let me know if you want me to look into this in more detail.

[bzbarsky]

OK, I looked at the latter issue at least. The difference between Gecko and servo there is in fact console being a namespace. This means that getting it does not seem to involve a shape guard or something (why, I dunno!). So we do reshape the window, but don't end up with shape guard failures as a result, so don't trigger https://bugzilla.mozilla.org/show_bug.cgi?id=1297604.

If I modify IonBuilder.cpp to not output a shape guard on the holder in IonBuilder::testCommonGetterSetter then the problem goes away in servo too. If I modify the testcase to look like this:

parent;
console.log('firstChild getter: ' + ((stop - start) / count * 1e6) + 'ns');

at the end of the function (so that there is a shape guard for the parent get, and then console gets lazily resolved), the problem pops up in Gecko as well.

So most immediately, fixing #13010 will help fix this somewhat for servo specifically, sorta kinda. But we really want to get traction on those spidermonkey issues too, I think.

[nox]

With console being a namespace:

± ./mach run tests/html/bindings_perf.html
firstChild getter: 0.6ns
firstChild getter: 0.44999999999999996ns
firstChild getter: 0.39999999999999997ns
firstChild getter: 0.39ns
firstChild getter: 0.43ns

Should we close this? :)

[jdm]

Seems like it!