From c585b5053fd8c4bed3632666313eb4dfa00368c8 Mon Sep 17 00:00:00 2001 From: Dan Mosedale Date: Mon, 7 Aug 2017 14:05:31 -0700 Subject: [PATCH 1/5] fix(telemetry): closes #3105, dont overwrite existing hero element time --- .../components/TopSites/TopSites.jsx | 25 +++++++----- .../content-src/components/TopSites.test.jsx | 38 +++++++++++++------ 2 files changed, 42 insertions(+), 21 deletions(-) diff --git a/system-addon/content-src/components/TopSites/TopSites.jsx b/system-addon/content-src/components/TopSites/TopSites.jsx index 4cded2bdbe..6365d3b536 100644 --- a/system-addon/content-src/components/TopSites/TopSites.jsx +++ b/system-addon/content-src/components/TopSites/TopSites.jsx @@ -105,7 +105,7 @@ class TopSitesPerfTimer extends React.Component { this.perfSvc = this.props.perfSvc || perfSvc; this._sendPaintedEvent = this._sendPaintedEvent.bind(this); - this._timestampSent = false; + this._timestampHandled = false; } componentDidMount() { @@ -131,11 +131,6 @@ class TopSitesPerfTimer extends React.Component { } _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 @@ -145,6 +140,19 @@ class TopSitesPerfTimer extends React.Component { return; } + // If we've already handled a timestamp, don't do it again + if (this._timestampHandled) { + return; + } + + // And if we haven't, we're doing so now, so remember that. + // Even if something goes wrong in the callback, we can't + // try again, as we'd be sending back the wrong data, and we + // have to do it here, so that other calls to this method + // while waiting for the next frame won't also try to handle + // handle it. + this._timestampHandled = true; + this._onNextFrame(this._sendPaintedEvent); } @@ -162,11 +170,10 @@ class TopSitesPerfTimer extends React.Component { } 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. + // to set this._timestampHandled to avoid going through this again. } - - this._timestampSent = true; } + render() { return (); } diff --git a/system-addon/test/unit/content-src/components/TopSites.test.jsx b/system-addon/test/unit/content-src/components/TopSites.test.jsx index 6d17853d67..03ade2d899 100644 --- a/system-addon/test/unit/content-src/components/TopSites.test.jsx +++ b/system-addon/test/unit/content-src/components/TopSites.test.jsx @@ -81,16 +81,40 @@ describe("", () => { assert.notCalled(stub); }); - it("should not call _onNextFrame if this._timestampSent is true", () => { + + it("should not call _onNextFrame if this._timestampHandled is true", () => { const wrapper = shallow(); const instance = wrapper.instance(); const stub = sandbox.stub(instance, "_onNextFrame"); - instance._timestampSent = true; + instance._timestampHandled = true; instance._maybeSendPaintedEvent(); assert.notCalled(stub); }); + + it("should set this._timestampHandled=true when called with Topsites.initialized === true", () => { + const wrapper = shallow(); + const instance = wrapper.instance(); + sandbox.stub(instance, "_onNextFrame"); + instance._timestampHandled = false; + + instance._maybeSendPaintedEvent(); + + assert.isTrue(instance._timestampHandled); + }); + it("should not set this._timestampHandled=true when called with Topsites.initialized === false", () => { + let props = {}; + Object.assign(props, DEFAULT_PROPS, {TopSites: {initialized: false}}); + const wrapper = shallow(); + const instance = wrapper.instance(); + sandbox.stub(instance, "_onNextFrame"); + instance._timestampHandled = false; + + instance._maybeSendPaintedEvent(); + + assert.isFalse(instance._timestampHandled); + }); }); describe("#_onNextFrame", () => { @@ -120,16 +144,6 @@ describe("", () => { assert.calledWithExactly(perfSvc.mark, "topsites_first_painted_ts"); }); - it("should set this._timestamp_sent to true", () => { - const wrapper = shallow(); - const instance = wrapper.instance(); - assert.isFalse(instance._timestampSent); - - wrapper.instance()._sendPaintedEvent(); - - assert.isTrue(instance._timestampSent); - }); - it("should send a SAVE_SESSION_PERF_DATA message with the result of perfSvc.getMostRecentAbsMarkStartByName two frames after mount", () => { sandbox.stub(perfSvc, "getMostRecentAbsMarkStartByName") .withArgs("topsites_first_painted_ts").returns(777); From 1817be97afcf43614846eef08ba179daec888a40 Mon Sep 17 00:00:00 2001 From: Dan Mosedale Date: Mon, 7 Aug 2017 15:06:17 -0700 Subject: [PATCH 2/5] fix(telemetry): make paint timings more precise --- .../components/TopSites/TopSites.jsx | 18 ++++++----- .../content-src/components/TopSites.test.jsx | 30 +++++++++---------- 2 files changed, 25 insertions(+), 23 deletions(-) diff --git a/system-addon/content-src/components/TopSites/TopSites.jsx b/system-addon/content-src/components/TopSites/TopSites.jsx index 6365d3b536..9460bce9de 100644 --- a/system-addon/content-src/components/TopSites/TopSites.jsx +++ b/system-addon/content-src/components/TopSites/TopSites.jsx @@ -117,17 +117,21 @@ class TopSitesPerfTimer extends React.Component { } /** - * Call the given callback when the subsequent animation frame - * (not the upcoming one) paints. + * Call the given callback after the upcoming frame paints. We're using + * a Promise rather than a setTimeout or double rFA, as Promise resolution + * is faster, as of this writing (Firefox 57 Nightly) - see #3105 for + * details. * * @param {Function} callback * * @returns void */ - _onNextFrame(callback) { - requestAnimationFrame(() => { - requestAnimationFrame(callback); - }); + _afterFramePaint(callback) { + new Promise(resolve => requestAnimationFrame(resolve)) + .then(callback).catch(reason => { + // eslint-disable-next-line no-console + console.warn("_afterFramePaint Promise rejected, reason:", reason); + }); } _maybeSendPaintedEvent() { @@ -153,7 +157,7 @@ class TopSitesPerfTimer extends React.Component { // handle it. this._timestampHandled = true; - this._onNextFrame(this._sendPaintedEvent); + this._afterFramePaint(this._sendPaintedEvent); } _sendPaintedEvent() { diff --git a/system-addon/test/unit/content-src/components/TopSites.test.jsx b/system-addon/test/unit/content-src/components/TopSites.test.jsx index 03ade2d899..22cddb465d 100644 --- a/system-addon/test/unit/content-src/components/TopSites.test.jsx +++ b/system-addon/test/unit/content-src/components/TopSites.test.jsx @@ -61,31 +61,31 @@ describe("", () => { }); describe("#_maybeSendPaintedEvent", () => { - it("should call _onNextFrame if props.TopSites.initialized is true", () => { + it("should call _afterFramePaint if props.TopSites.initialized is true", () => { const wrapper = shallow(); const instance = wrapper.instance(); - const stub = sandbox.stub(instance, "_onNextFrame"); + const stub = sandbox.stub(instance, "_afterFramePaint"); instance._maybeSendPaintedEvent(); assert.calledOnce(stub); assert.calledWithExactly(stub, instance._sendPaintedEvent); }); - it("should not call _onNextFrame if props.TopSites.initialized is false", () => { + it("should not call _afterFramePaint if props.TopSites.initialized is false", () => { sandbox.stub(DEFAULT_PROPS.TopSites, "initialized").value(false); const wrapper = shallow(); const instance = wrapper.instance(); - const stub = sandbox.stub(instance, "_onNextFrame"); + const stub = sandbox.stub(instance, "_afterFramePaint"); instance._maybeSendPaintedEvent(); assert.notCalled(stub); }); - it("should not call _onNextFrame if this._timestampHandled is true", () => { + it("should not call _afterFramePaint if this._timestampHandled is true", () => { const wrapper = shallow(); const instance = wrapper.instance(); - const stub = sandbox.stub(instance, "_onNextFrame"); + const stub = sandbox.stub(instance, "_afterFramePaint"); instance._timestampHandled = true; instance._maybeSendPaintedEvent(); @@ -96,7 +96,7 @@ describe("", () => { it("should set this._timestampHandled=true when called with Topsites.initialized === true", () => { const wrapper = shallow(); const instance = wrapper.instance(); - sandbox.stub(instance, "_onNextFrame"); + sandbox.stub(instance, "_afterFramePaint"); instance._timestampHandled = false; instance._maybeSendPaintedEvent(); @@ -108,7 +108,7 @@ describe("", () => { Object.assign(props, DEFAULT_PROPS, {TopSites: {initialized: false}}); const wrapper = shallow(); const instance = wrapper.instance(); - sandbox.stub(instance, "_onNextFrame"); + sandbox.stub(instance, "_afterFramePaint"); instance._timestampHandled = false; instance._maybeSendPaintedEvent(); @@ -117,19 +117,17 @@ describe("", () => { }); }); - describe("#_onNextFrame", () => { - it("should call callback one frame after the current one", () => { - const callback = sandbox.spy(); + describe("#_afterFramePaint", () => { + it("should call callback after the requestAnimationFrame callback returns", done => { + this.callback = () => done(); + sandbox.spy(this, "callback"); const wrapper = shallow(); - const instance = wrapper.instance(); - instance._onNextFrame(callback); - mockRaf.step({count: 1}); - assert.notCalled(callback); + instance._afterFramePaint(this.callback); + assert.notCalled(this.callback); mockRaf.step({count: 1}); - assert.calledOnce(callback); }); }); From cac31b3c99587997bd73b4d99352c2fa3796b394 Mon Sep 17 00:00:00 2001 From: Dan Mosedale Date: Wed, 9 Aug 2017 12:09:05 -0700 Subject: [PATCH 3/5] Fill comment paragraph at 80 columns --- .../content-src/components/TopSites/TopSites.jsx | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/system-addon/content-src/components/TopSites/TopSites.jsx b/system-addon/content-src/components/TopSites/TopSites.jsx index 9460bce9de..f687fd09a1 100644 --- a/system-addon/content-src/components/TopSites/TopSites.jsx +++ b/system-addon/content-src/components/TopSites/TopSites.jsx @@ -149,12 +149,11 @@ class TopSitesPerfTimer extends React.Component { return; } - // And if we haven't, we're doing so now, so remember that. - // Even if something goes wrong in the callback, we can't - // try again, as we'd be sending back the wrong data, and we - // have to do it here, so that other calls to this method - // while waiting for the next frame won't also try to handle - // handle it. + // And if we haven't, we're doing so now, so remember that. Even if + // something goes wrong in the callback, we can't try again, as we'd be + // sending back the wrong data, and we have to do it here, so that other + // calls to this method while waiting for the next frame won't also try to + // handle handle it. this._timestampHandled = true; this._afterFramePaint(this._sendPaintedEvent); From 8e6b659dc009d35ecb049e2e6e94760db26986a3 Mon Sep 17 00:00:00 2001 From: Dan Mosedale Date: Wed, 9 Aug 2017 13:36:46 -0700 Subject: [PATCH 4/5] Fix outdated comment --- system-addon/test/unit/content-src/components/TopSites.test.jsx | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/system-addon/test/unit/content-src/components/TopSites.test.jsx b/system-addon/test/unit/content-src/components/TopSites.test.jsx index 22cddb465d..734d4a7cea 100644 --- a/system-addon/test/unit/content-src/components/TopSites.test.jsx +++ b/system-addon/test/unit/content-src/components/TopSites.test.jsx @@ -142,7 +142,7 @@ describe("", () => { assert.calledWithExactly(perfSvc.mark, "topsites_first_painted_ts"); }); - it("should send a SAVE_SESSION_PERF_DATA message with the result of perfSvc.getMostRecentAbsMarkStartByName two frames after mount", () => { + it("should send a SAVE_SESSION_PERF_DATA message with the result of perfSvc.getMostRecentAbsMarkStartByName", () => { sandbox.stub(perfSvc, "getMostRecentAbsMarkStartByName") .withArgs("topsites_first_painted_ts").returns(777); const spy = sandbox.spy(DEFAULT_PROPS, "dispatch"); From c74dff8112f82cf24db3786148c29bcbaf19cd62 Mon Sep 17 00:00:00 2001 From: Dan Mosedale Date: Wed, 9 Aug 2017 13:50:12 -0700 Subject: [PATCH 5/5] Switch out the promise to setTimeout --- .../components/TopSites/TopSites.jsx | 20 ++++++++++--------- .../content-src/components/TopSites.test.jsx | 3 +++ 2 files changed, 14 insertions(+), 9 deletions(-) diff --git a/system-addon/content-src/components/TopSites/TopSites.jsx b/system-addon/content-src/components/TopSites/TopSites.jsx index f687fd09a1..d2db3b453d 100644 --- a/system-addon/content-src/components/TopSites/TopSites.jsx +++ b/system-addon/content-src/components/TopSites/TopSites.jsx @@ -117,21 +117,23 @@ class TopSitesPerfTimer extends React.Component { } /** - * Call the given callback after the upcoming frame paints. We're using - * a Promise rather than a setTimeout or double rFA, as Promise resolution - * is faster, as of this writing (Firefox 57 Nightly) - see #3105 for - * details. + * Call the given callback after the upcoming frame paints. + * + * @note Both setTimeout and requestAnimationFrame are throttled when the page + * is hidden, so this will give incorrect results in that case. We'll want to + * filter out preloaded tabs, and otherwise, this is presumably, a fairly rare + * case that will get lost in the noise. If we decide that it's important to + * find out when something that's hidden has "painted", however, another + * option is to post a message to this window. That should happen even faster + * than setTimeout, and, at least as of this writing, it's not throttled in + * hidden windows in Firefox. * * @param {Function} callback * * @returns void */ _afterFramePaint(callback) { - new Promise(resolve => requestAnimationFrame(resolve)) - .then(callback).catch(reason => { - // eslint-disable-next-line no-console - console.warn("_afterFramePaint Promise rejected, reason:", reason); - }); + requestAnimationFrame(() => setTimeout(callback, 0)); } _maybeSendPaintedEvent() { diff --git a/system-addon/test/unit/content-src/components/TopSites.test.jsx b/system-addon/test/unit/content-src/components/TopSites.test.jsx index 734d4a7cea..4d8ae02f11 100644 --- a/system-addon/test/unit/content-src/components/TopSites.test.jsx +++ b/system-addon/test/unit/content-src/components/TopSites.test.jsx @@ -119,6 +119,9 @@ describe("", () => { describe("#_afterFramePaint", () => { it("should call callback after the requestAnimationFrame callback returns", done => { + // Setting the callback to done is the test that it does finally get + // called at the correct time, after the event loop ticks again. + // If it doesn't get called, this test will time out. this.callback = () => done(); sandbox.spy(this, "callback"); const wrapper = shallow();