fix(telemetry): Don't overwrite existing hero element time and make p…

…aint timings more precise

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() {
@@ -117,25 +117,30 @@ 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.
+   *
+   * @note Both setTimeout and requestAnimationFrame are throttled when the page
+   * is hidden, so this callback may get called up to a second or so after the
+   * requestAnimationFrame "paint" for hidden tabs.
+   *
+   * Newtabs hidden while loading will presumably be fairly rare (other than
+   * preloaded tabs, which we will be filtering out on the server side), so such
+   * cases should 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
    */
-  _onNextFrame(callback) {
-    requestAnimationFrame(() => {
-      requestAnimationFrame(callback);
-    });
+  _afterFramePaint(callback) {
+    requestAnimationFrame(() => setTimeout(callback, 0));
   }
 
   _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,7 +150,19 @@ class TopSitesPerfTimer extends React.Component {
       return;
     }
 
-    this._onNextFrame(this._sendPaintedEvent);
+    // 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._afterFramePaint(this._sendPaintedEvent);
   }
 
   _sendPaintedEvent() {
@@ -162,11 +179,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 (<TopSites {...this.props} />);
   }

system-addon/test/unit/content-src/components/TopSites.test.jsx

@@ -61,51 +61,76 @@ describe("<TopSitesPerfTimer>", () => {
   });
 
   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(<TopSitesPerfTimer {...DEFAULT_PROPS} />);
       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(<TopSitesPerfTimer {...DEFAULT_PROPS} />);
       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._timestampSent is true", () => {
+
+    it("should not call _afterFramePaint if this._timestampHandled is true", () => {
       const wrapper = shallow(<TopSitesPerfTimer {...DEFAULT_PROPS} />);
       const instance = wrapper.instance();
-      const stub = sandbox.stub(instance, "_onNextFrame");
-      instance._timestampSent = true;
+      const stub = sandbox.stub(instance, "_afterFramePaint");
+      instance._timestampHandled = true;
 
       instance._maybeSendPaintedEvent();
 
       assert.notCalled(stub);
     });
-  });
 
-  describe("#_onNextFrame", () => {
-    it("should call callback one frame after the current one", () => {
-      const callback = sandbox.spy();
+    it("should set this._timestampHandled=true when called with Topsites.initialized === true", () => {
       const wrapper = shallow(<TopSitesPerfTimer {...DEFAULT_PROPS} />);
+      const instance = wrapper.instance();
+      sandbox.stub(instance, "_afterFramePaint");
+      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(<TopSitesPerfTimer {...props} />);
       const instance = wrapper.instance();
-      instance._onNextFrame(callback);
+      sandbox.stub(instance, "_afterFramePaint");
+      instance._timestampHandled = false;
 
-      mockRaf.step({count: 1});
-      assert.notCalled(callback);
+      instance._maybeSendPaintedEvent();
+
+      assert.isFalse(instance._timestampHandled);
+    });
+  });
 
+  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(<TopSitesPerfTimer {...DEFAULT_PROPS} />);
+      const instance = wrapper.instance();
+
+      instance._afterFramePaint(this.callback);
+
+      assert.notCalled(this.callback);
       mockRaf.step({count: 1});
-      assert.calledOnce(callback);
     });
   });
 
@@ -120,17 +145,7 @@ describe("<TopSitesPerfTimer>", () => {
       assert.calledWithExactly(perfSvc.mark, "topsites_first_painted_ts");
     });
 
-    it("should set this._timestamp_sent to true", () => {
-      const wrapper = shallow(<TopSitesPerfTimer {...DEFAULT_PROPS} />);
-      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", () => {
+    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");