hero element timestamp sent too many times

[dmose]

So I found the bug that's causing the the extra topsites_first_painted_ts in https://bugzilla.mozilla.org/show_bug.cgi?id=1387852

activity-stream/system-addon/content-src/components/TopSites/TopSites.jsx

Lines 133 to 169 in 3b2f4a3

	_maybeSendPaintedEvent() {
	// If we've already saved a timestamp for this session, don't do so again.
	if (this._timestampSent) {
	return;
	}
	// We don't want this to ever happen, but sometimes it does. And when it
	// does (typically on the first newtab at startup time calling
	// componentDidMount), the paint(s) we care about will be later (eg
	// in a subsequent componentDidUpdate).
	if (!this.props.TopSites.initialized) {
	// XXX should send bad event
	return;
	}
	this._onNextFrame(this._sendPaintedEvent);
	}
	_sendPaintedEvent() {
	this.perfSvc.mark("topsites_first_painted_ts");
	try {
	let topsites_first_painted_ts = this.perfSvc
	.getMostRecentAbsMarkStartByName("topsites_first_painted_ts");
	this.props.dispatch(ac.SendToMain({
	type: at.SAVE_SESSION_PERF_DATA,
	data: {topsites_first_painted_ts}
	}));
	} catch (ex) {
	// If this failed, it's likely because the `privacy.resistFingerprinting`
	// pref is true. We should at least not blow up, and should continue
	// to set this._timestampSent to avoid going through this again.
	}
	this._timestampSent = true;
	}

What's happening is that _maybeSendPaintedEvent is relying on this._timestampSent to guard against sending events for all 12 screenshots as they come in, one after another. Unfortunately, there's a race here: _sendPaintedEvent only set this._timestampSent on the next frame. Which means that if a bunch of the screenshots come in before the next frame is painted, they'll all get sent too.

We will likely want to uplift this fix to 56 so that we get useful topsites_first_painted_ts data from the shield study.

[Mardak]

In terms of "useful data" the data sent should still be usable. Just that we need to be aware that there might be multiple from the same session, so only use the earliest timestamp and ignore the rest.

@emtwo @ncloudioj how important is this to fix for 56?

[dmose]

There won't be multiple hero element timestamps; rather, the last (screenshot) _sendPaintedEvent that gets executed (maybe it happens in order, maybe not; depends on how the new 3-queue scheduler is working these days) will win and overwrite whatever came before. I kinda suspect this won't be a huge deal, but I don't really know.

[Mardak]

Looking at the timings of the https://perfht.ml/2fjij4J from the linked bug…

15.155
15.155
15.155
15.156
15.156

then

17.156
17.157
17.157
17.158
17.158
17.159
17.160
17.161

So it seems that being in a non-visible preloaded browser definitely slows down requestAnimationFrames to looks like 1 or 2 seconds? So the timing values can be quite different. Although then again is the draw time of a non-visible hero element what we want in the first place?

[dmose]

Assuming that the preloaded newtab starts as soon as the first non-preloaded one opens (which is what I would expect), that does sound likely the right interpretation.

One thing we can do about that is to switch from double-RFA to RFA+setTimeout(0) , which seems to be the current "best-practice", as far as that goes.

You're right that the draw time of the non-visible stuff is less interesting; it becomes a bit more interesting when the thing is painted partially while it's invisible and partially while it's visible. But that's presumably going to be a tiny percentage of the paints, so it's unlikely worth losing much sleep over.

Note that one of the things I'm working on right now is figuring out how to tell apart pre-rendered and non-prerendered newtabs, as what we're interested in in those two case is fairly different, so we need to separate them out in the dashboards.

[dmose]

Turns out that @Mardak discovered that Promise.resolve().then(); resolves faster than setTimeout(0), at least in current Nightly.

We also suspect that it'll work better than setTimeout for the preloaded browser, which is not visibile, and presumably as a result has setTimeout and requestAnimationFrame throttled.

So I'll cons up a patch with that in it too.

@digitarald thoughts on whether this might have any anticipated problems?

[dmose]

e.g. could the promise resolve after the rFA callback, but before the frame itself actual finishes painting?

[digitarald]

Reading the first comments I can confirm that this metric is not expected to work in a background window. Background windows don't paint, so I would guard the measure with document.hidden, not measuring the paint delay for backgrounded pages.

If Promises are handled closer after vsync then they are a good alternative. Timeouts can be tricky and have fewer guarantees.

[Mardak]

@dmose here's some more timing examples that you can run on some page's web console:

ts = performance.now();
_ = name => () => console.log((performance.now() - ts).toFixed(1).padStart(6), name);
setTimeout(() => {
  _("timeout-start")();
  document.body.innerHTML = Math.random();
  _("timeout-mid")();
  p = new Promise(resolve => requestAnimationFrame(() => {
    _("raf-start")();
    resolve();
    _("raf-mid")();
    setTimeout(_("raf->timeout"));
    requestAnimationFrame(_("raf->raf"));
    setTimeout(_("2.raf->timeout"));
    requestAnimationFrame(_("2.raf->raf"));
    _("raf-end")();
  }));
  p.then(_("raf->resolved"));
  requestAnimationFrame(_("other raf"));
  p.then(_("2.raf->resolved"));
  requestAnimationFrame(_("2.other raf"));
  _("timeout-end")();
}, 5000);
_("waiting for timeout, go switch away")();

If I run that without switching away:

   0.1 waiting for timeout, go switch away 
5004.0 timeout-start 
5005.5 timeout-mid 
5006.4 timeout-end 
5016.9 raf-start 
5017.8 raf-mid 
5018.5 raf-end 
5019.2 other raf 
5019.6 2.other raf 
5024.0 raf->resolved 
5024.7 2.raf->resolved 
5025.2 raf->timeout 
5025.6 2.raf->timeout 
5034.7 raf->raf 
5035.6 2.raf->raf 

And with switching away:

   0.1 waiting for timeout, go switch away 
5001.6 timeout-start 
5003.6 timeout-mid 
5004.9 timeout-end 
6004.2 raf-start 
6005.6 raf-mid 
6006.8 raf-end 
6007.4 other raf 
6007.8 2.other raf 
6008.6 raf->resolved 
6009.2 2.raf->resolved 
7007.3 raf->timeout 
7008.3 2.raf->timeout 
7602.8 raf->raf 
7603.4 2.raf->raf 

So for _maybeSendPaintedEvent, we should be able to do:

new Promise(resolve => requestAnimationFrame(resolve)).then(this._sendPaintedEvent);

And interesting note from the switched-away numbers:
raf is throttled to wait 1 second (1fps) before triggering on the intial raf where there was a layout change
setTimeout is also throttled to wait 1 second
the second raf is throttled to wait 1.5 seconds (0.66fps) when there's no additional change

This is compared to when in focus, raf resolves in ~17ms (60fps)

[dmose]

That all looks good to me, though I don't see where you're getting the 17ms number from...

[dmose]

Oh, just assuming one frame is ~16ms?

[dmose]

Reading the first comments I can confirm that this metric is not expected to work in a background window. Background windows don't paint, so I would guard the measure with document.hidden, not measuring the paint delay for backgrounded pages.

That's an interesting point, I'll spin this off to another bug, as there are probably multiple things we might choose not to measure while things are hidden, and that will affect our dashboarding as well.

If Promises are handled closer after vsync then they are a good alternative. Timeouts can be tricky and have fewer guarantees.

@digitarald As it turns out, the Promise might currently resolve after vsync, but before too long, it'll be resolving before vsync. smaug did say, however, that posting a message to our own window would work quickly and (for the moment at least) not be throttled. That said, I think we'll probably stick with setTimeout as being good enough, since we will be throwing out / not collecting preloaded pages.

[Mardak]

Uplifted to firefox-56 branch: 58442c2