Bug 1525391 - Collect telemetry for request time and cache age for Pocket. r=Mardak a=lizzard
authork88hudson <k88hudson@gmail.com>
Sat, 16 Feb 2019 00:49:46 +0200
changeset 515991 86bd7fce23cdf0b425d4abb2e0f439f243291e1f
parent 515990 7f0cb549e3d3f3f532c93898c8177c3d7921cd45
child 515992 6462ee7b5df4a5c925ed0847755a9f22c4a4a9ca
push id1953
push userffxbld-merge
push dateMon, 11 Mar 2019 12:10:20 +0000
treeherdermozilla-release@9c35dcbaa899 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersMardak, lizzard
bugs1525391
milestone66.0
Bug 1525391 - Collect telemetry for request time and cache age for Pocket. r=Mardak a=lizzard Reviewers: nanj, Mardak Reviewed By: nanj, Mardak Bug #: 1525391 Differential Revision: https://phabricator.services.mozilla.com/D19973
browser/components/newtab/docs/v2-system-addon/data_events.md
browser/components/newtab/lib/DiscoveryStreamFeed.jsm
browser/components/newtab/test/unit/lib/DiscoveryStreamFeed.test.js
--- a/browser/components/newtab/docs/v2-system-addon/data_events.md
+++ b/browser/components/newtab/docs/v2-system-addon/data_events.md
@@ -734,16 +734,88 @@ These report any failures during domain 
   "client_id": "26288a14-5cc4-d14f-ae0a-bb01ef45be9c",
   "addon_version": "20180710100040",
   "locale": "en-US",
   "user_prefs": 7,
   "event": "PERSONALIZATION_V2_CREATE_INTEREST_VECTOR_ERROR"
 }
 ```
 
+### Discovery Stream performance pings
+
+#### Request time of layout feed in ms
+
+```js
+{
+  "action": "activity_stream_performance_event",
+  "client_id": "26288a14-5cc4-d14f-ae0a-bb01ef45be9c",
+  "addon_version": "20180710100040",
+  "locale": "en-US",
+  "user_prefs": 7,
+  "event": "LAYOUT_REQUEST_TIME",
+  "value": 42
+}
+```
+
+#### Request time of SPOCS feed in ms
+
+```js
+{
+  "action": "activity_stream_performance_event",
+  "client_id": "26288a14-5cc4-d14f-ae0a-bb01ef45be9c",
+  "addon_version": "20180710100040",
+  "locale": "en-US",
+  "user_prefs": 7,
+  "event": "SPOCS_REQUEST_TIME",
+  "value": 42
+}
+```
+
+#### Request time of component feed feed in ms
+
+```js
+{
+  "action": "activity_stream_performance_event",
+  "client_id": "26288a14-5cc4-d14f-ae0a-bb01ef45be9c",
+  "addon_version": "20180710100040",
+  "locale": "en-US",
+  "user_prefs": 7,
+  "event": "COMPONENT_FEED_REQUEST_TIME",
+  "value": 42
+}
+```
+
+#### Request time of total Discovery Stream feed in ms
+
+```js
+{
+  "action": "activity_stream_performance_event",
+  "client_id": "26288a14-5cc4-d14f-ae0a-bb01ef45be9c",
+  "addon_version": "20180710100040",
+  "locale": "en-US",
+  "user_prefs": 7,
+  "event": "DS_FEED_TOTAL_REQUEST_TIME",
+  "value": 136
+}
+```
+
+#### Cache age of Discovery Stream feed in second
+
+```js
+{
+  "action": "activity_stream_performance_event",
+  "client_id": "26288a14-5cc4-d14f-ae0a-bb01ef45be9c",
+  "addon_version": "20180710100040",
+  "locale": "en-US",
+  "user_prefs": 7,
+  "event": "DS_CACHE_AGE_IN_SEC",
+  "value": 1800 // 30 minutes
+}
+```
+
 ## Undesired event pings
 
 These pings record the undesired events happen in the addon for further investigation.
 
 ### Addon initialization failure
 
 This reports when the addon fails to initialize
 
--- a/browser/components/newtab/lib/DiscoveryStreamFeed.jsm
+++ b/browser/components/newtab/lib/DiscoveryStreamFeed.jsm
@@ -1,16 +1,17 @@
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 "use strict";
 
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 XPCOMUtils.defineLazyGlobalGetters(this, ["fetch"]);
 ChromeUtils.import("resource://gre/modules/Services.jsm");
+ChromeUtils.defineModuleGetter(this, "perfService", "resource://activity-stream/common/PerfService.jsm");
 
 const {actionTypes: at, actionCreators: ac} = ChromeUtils.import("resource://activity-stream/common/Actions.jsm", {});
 const {PersistentCache} = ChromeUtils.import("resource://activity-stream/lib/PersistentCache.jsm", {});
 
 const CACHE_KEY = "discovery_stream";
 const LAYOUT_UPDATE_TIME = 30 * 60 * 1000; // 30 minutes
 const STARTUP_CACHE_EXPIRE_TIME = 7 * 24 * 60 * 60 * 1000; // 1 week
 const COMPONENT_FEEDS_UPDATE_TIME = 30 * 60 * 1000; // 30 minutes
@@ -137,18 +138,20 @@ this.DiscoveryStreamFeed = class Discove
       expirationPerComponent.spocs ||
       expirationPerComponent.feeds;
   }
 
   async loadLayout(sendUpdate, isStartup) {
     const cachedData = await this.cache.get() || {};
     let {layout: layoutResponse} = cachedData;
     if (this.isExpired({cachedData, key: "layout", isStartup})) {
+      const start = perfService.absNow();
       layoutResponse = await this.fetchFromEndpoint(this.config.layout_endpoint);
       if (layoutResponse && layoutResponse.layout) {
+        this.layoutRequestTime = Math.round(perfService.absNow() - start);
         layoutResponse._timestamp = Date.now();
         await this.cache.set("layout", layoutResponse);
       } else {
         Cu.reportError("No response for response.layout prop");
       }
     }
 
     if (layoutResponse && layoutResponse.layout) {
@@ -235,34 +238,43 @@ this.DiscoveryStreamFeed = class Discove
 
   async loadComponentFeeds(sendUpdate, isStartup) {
     const {DiscoveryStream} = this.store.getState();
 
     if (!DiscoveryStream || !DiscoveryStream.layout) {
       return;
     }
 
+    // Reset the flag that indicates whether or not at least one API request
+    // was issued to fetch the component feed in `getComponentFeed()`.
+    this.componentFeedFetched = false;
+    const start = perfService.absNow();
     const {newFeedsPromises, newFeeds} = this.buildFeedPromises(DiscoveryStream.layout, isStartup);
 
     // Each promise has a catch already built in, so no need to catch here.
     await Promise.all(newFeedsPromises);
+    if (this.componentFeedFetched) {
+      this.componentFeedRequestTime = Math.round(perfService.absNow() - start);
+    }
     await this.cache.set("feeds", newFeeds);
     sendUpdate({type: at.DISCOVERY_STREAM_FEEDS_UPDATE, data: newFeeds});
   }
 
   async loadSpocs(sendUpdate, isStartup) {
     const cachedData = await this.cache.get() || {};
     let spocs;
 
     if (this.showSpocs) {
       spocs = cachedData.spocs;
       if (this.isExpired({cachedData, key: "spocs", isStartup})) {
         const endpoint = this.store.getState().DiscoveryStream.spocs.spocs_endpoint;
+        const start = perfService.absNow();
         const spocsResponse = await this.fetchFromEndpoint(endpoint);
         if (spocsResponse) {
+          this.spocsRequestTime = Math.round(perfService.absNow() - start);
           spocs = {
             lastUpdated: Date.now(),
             data: spocsResponse,
           };
 
           this.cleanUpCampaignImpressionPref(spocs.data);
           await this.cache.set("spocs", spocs);
         } else {
@@ -342,16 +354,17 @@ this.DiscoveryStreamFeed = class Discove
 
   async getComponentFeed(feedUrl, isStartup) {
     const cachedData = await this.cache.get() || {};
     const {feeds} = cachedData;
     let feed = feeds ? feeds[feedUrl] : null;
     if (this.isExpired({cachedData, key: "feed", url: feedUrl, isStartup})) {
       const feedResponse = await this.fetchFromEndpoint(feedUrl);
       if (feedResponse) {
+        this.componentFeedFetched = true;
         feed = {
           lastUpdated: Date.now(),
           data: feedResponse,
         };
       } else {
         Cu.reportError("No response for feed");
       }
     }
@@ -398,25 +411,109 @@ this.DiscoveryStreamFeed = class Discove
     ]);
     if (isStartup) {
       await this._maybeUpdateCachedData();
     }
 
     this.loaded = true;
   }
 
+  /**
+   * Reports the cache age in second for Discovery Stream.
+   */
+  async reportCacheAge() {
+    const cachedData = await this.cache.get() || {};
+    const {layout, spocs, feeds} = cachedData;
+    let cacheAge = Date.now();
+    let updated = false;
+
+    if (layout && layout._timestamp && layout._timestamp < cacheAge) {
+      updated = true;
+      cacheAge = layout._timestamp;
+    }
+
+    if (spocs && spocs.lastUpdated && spocs.lastUpdated < cacheAge) {
+      updated = true;
+      cacheAge = spocs.lastUpdated;
+    }
+
+    if (feeds) {
+      Object.keys(feeds).forEach(url => {
+        const feed = feeds[url];
+        if (feed.lastUpdated && feed.lastUpdated < cacheAge) {
+          updated = true;
+          cacheAge = feed.lastUpdated;
+        }
+      });
+    }
+
+    if (updated) {
+      this.store.dispatch(ac.PerfEvent({
+        event: "DS_CACHE_AGE_IN_SEC",
+        value: Math.round((Date.now() - cacheAge) / 1000),
+      }));
+    }
+  }
+
+  /**
+   * Reports various time durations when the feed is requested from endpoint for
+   * the first time. This could happen on the browser start-up, or the pref changes
+   * of discovery stream.
+   *
+   * Metrics to be reported:
+   *   - Request time for layout endpoint
+   *   - Request time for feed endpoint
+   *   - Request time for spoc endpoint
+   *   - Total request time for data completeness
+   */
+  reportRequestTime() {
+    if (this.layoutRequestTime) {
+      this.store.dispatch(ac.PerfEvent({
+        event: "LAYOUT_REQUEST_TIME",
+        value: this.layoutRequestTime,
+      }));
+    }
+    if (this.spocsRequestTime) {
+      this.store.dispatch(ac.PerfEvent({
+        event: "SPOCS_REQUEST_TIME",
+        value: this.spocsRequestTime,
+      }));
+    }
+    if (this.componentFeedRequestTime) {
+      this.store.dispatch(ac.PerfEvent({
+        event: "COMPONENT_FEED_REQUEST_TIME",
+        value: this.componentFeedRequestTime,
+      }));
+    }
+    if (this.totalRequestTime) {
+      this.store.dispatch(ac.PerfEvent({
+        event: "DS_FEED_TOTAL_REQUEST_TIME",
+        value: this.totalRequestTime,
+      }));
+    }
+  }
+
   async enable() {
+    // Note that cache age needs to be reported prior to refreshAll.
+    await this.reportCacheAge();
+    const start = perfService.absNow();
     await this.refreshAll({updateOpenTabs: true, isStartup: true});
+    this.totalRequestTime = Math.round(perfService.absNow() - start);
+    this.reportRequestTime();
   }
 
   async disable() {
     await this.clearCache();
     // Reset reducer
     this.store.dispatch(ac.BroadcastToContent({type: at.DISCOVERY_STREAM_LAYOUT_RESET}));
     this.loaded = false;
+    this.layoutRequestTime = undefined;
+    this.spocsRequestTime = undefined;
+    this.componentFeedRequestTime = undefined;
+    this.totalRequestTime = undefined;
   }
 
   async clearCache() {
     await this.cache.set("layout", {});
     await this.cache.set("feeds", {});
     await this.cache.set("spocs", {});
   }
 
--- a/browser/components/newtab/test/unit/lib/DiscoveryStreamFeed.test.js
+++ b/browser/components/newtab/test/unit/lib/DiscoveryStreamFeed.test.js
@@ -179,16 +179,29 @@ describe("DiscoveryStreamFeed", () => {
 
         await feed.loadComponentFeeds(feed.store.dispatch);
 
         assert.calledOnce(global.Promise.all);
         const {args} = global.Promise.all.firstCall;
         assert.equal(args[0].length, 3);
       }
     );
+
+    it("should not record the request time if no fetch request was issued", async () => {
+      const fakeComponents = {components: []};
+      const fakeLayout = [fakeComponents, {components: [{}]}, {}];
+      fakeDiscoveryStream = {DiscoveryStream: {layout: fakeLayout}};
+      fakeCache = {feeds: {"foo.com": {"lastUpdated": Date.now(), "data": "data"}}};
+      sandbox.stub(feed.cache, "get").returns(Promise.resolve(fakeCache));
+      feed.componentFeedRequestTime = undefined;
+
+      await feed.loadComponentFeeds(feed.store.dispatch);
+
+      assert.isUndefined(feed.componentFeedRequestTime);
+    });
   });
 
   describe("#getComponentFeed", () => {
     it("should fetch fresh data if cache is empty", async () => {
       const fakeCache = {};
       sandbox.stub(feed.cache, "get").returns(Promise.resolve(fakeCache));
       sandbox.stub(feed, "fetchFromEndpoint").resolves("data");
 
@@ -581,21 +594,25 @@ describe("DiscoveryStreamFeed", () => {
     it("should be .loaded=false before initialization", () => {
       assert.isFalse(feed.loaded);
     });
     it("should load data, add pref observer, and set .loaded=true if config.enabled is true", async () => {
       sandbox.stub(feed.cache, "set").returns(Promise.resolve());
       configPrefStub.returns(JSON.stringify({enabled: true}));
       sandbox.stub(feed, "loadLayout").returns(Promise.resolve());
       sandbox.stub(global.Services.prefs, "addObserver");
+      sandbox.stub(feed, "reportCacheAge").resolves();
+      sandbox.spy(feed, "reportRequestTime");
 
       await feed.onAction({type: at.INIT});
 
       assert.calledOnce(feed.loadLayout);
       assert.calledWith(global.Services.prefs.addObserver, CONFIG_PREF_NAME, feed);
+      assert.calledOnce(feed.reportCacheAge);
+      assert.calledOnce(feed.reportRequestTime);
       assert.isTrue(feed.loaded);
     });
   });
 
   describe("#onAction: DISCOVERY_STREAM_CONFIG_SET_VALUE", () => {
     it("should add the new value to the pref without changing the existing values", async () => {
       sandbox.stub(global.Services.prefs, "setStringPref");
       configPrefStub.returns(JSON.stringify({enabled: true}));
@@ -805,17 +822,17 @@ describe("DiscoveryStreamFeed", () => {
     beforeEach(() => {
       sandbox.stub(feed, "loadLayout").resolves();
       sandbox.stub(feed, "loadComponentFeeds").resolves();
       sandbox.stub(feed, "loadSpocs").resolves();
       sandbox.spy(feed.store, "dispatch");
       Object.defineProperty(feed, "showSpocs", {get: () => true});
     });
 
-    it("should call layout, component, spocs update functions", async () => {
+    it("should call layout, component, spocs update and telemetry reporting functions", async () => {
       await feed.refreshAll();
 
       assert.calledOnce(feed.loadLayout);
       assert.calledOnce(feed.loadComponentFeeds);
       assert.calledOnce(feed.loadSpocs);
     });
     it("should pass in dispatch wrapped with broadcast if options.updateOpenTabs is true", async () => {
       await feed.refreshAll({updateOpenTabs: true});
@@ -918,9 +935,82 @@ describe("DiscoveryStreamFeed", () => {
 
         assert.calledOnce(feed.fetchFromEndpoint);
         // Once from cache, once to update the store
         assert.calledTwice(feed.store.dispatch);
         assert.equal(feed.store.dispatch.firstCall.args[0].type, at.DISCOVERY_STREAM_FEEDS_UPDATE);
       });
     });
   });
+
+  describe("#reportCacheAge", () => {
+    let cache;
+    const cacheAge = 30;
+    beforeEach(() => {
+      cache = {
+        layout: {_timestamp: Date.now() - 10 * 1000},
+        feeds: {"foo.com": {lastUpdated: Date.now() - cacheAge * 1000}},
+        spocs: {lastUpdated: Date.now() - 20 * 1000},
+      };
+      sandbox.stub(feed.cache, "get").resolves(cache);
+    });
+
+    it("should report the oldest lastUpdated date as the cache age", async () => {
+      sandbox.spy(feed.store, "dispatch");
+      feed.loaded = false;
+      await feed.reportCacheAge();
+
+      assert.calledOnce(feed.store.dispatch);
+
+      const [action] = feed.store.dispatch.firstCall.args;
+      assert.equal(action.type, at.TELEMETRY_PERFORMANCE_EVENT);
+      assert.equal(action.data.event, "DS_CACHE_AGE_IN_SEC");
+      assert.isAtLeast(action.data.value, cacheAge);
+      feed.loaded = true;
+    });
+  });
+
+  describe("#reportRequestTime", () => {
+    let cache;
+    const cacheAge = 30;
+    beforeEach(() => {
+      cache = {
+        layout: {_timeStamp: Date.now() - 10 * 1000},
+        feeds: {"foo.com": {lastUpdated: Date.now() - cacheAge * 1000}},
+        spocs: {lastUpdated: Date.now() - 20 * 1000},
+      };
+      sandbox.stub(feed.cache, "get").resolves(cache);
+    });
+
+    it("should report all the request times", async () => {
+      sandbox.spy(feed.store, "dispatch");
+      feed.loaded = false;
+      feed.layoutRequestTime = 1000;
+      feed.spocsRequestTime = 2000;
+      feed.componentFeedRequestTime = 3000;
+      feed.totalRequestTime = 5000;
+      feed.reportRequestTime();
+
+      assert.equal(feed.store.dispatch.callCount, 4);
+
+      let [action] = feed.store.dispatch.getCall(0).args;
+      assert.equal(action.type, at.TELEMETRY_PERFORMANCE_EVENT);
+      assert.equal(action.data.event, "LAYOUT_REQUEST_TIME");
+      assert.equal(action.data.value, 1000);
+
+      [action] = feed.store.dispatch.getCall(1).args;
+      assert.equal(action.type, at.TELEMETRY_PERFORMANCE_EVENT);
+      assert.equal(action.data.event, "SPOCS_REQUEST_TIME");
+      assert.equal(action.data.value, 2000);
+
+      [action] = feed.store.dispatch.getCall(2).args;
+      assert.equal(action.type, at.TELEMETRY_PERFORMANCE_EVENT);
+      assert.equal(action.data.event, "COMPONENT_FEED_REQUEST_TIME");
+      assert.equal(action.data.value, 3000);
+
+      [action] = feed.store.dispatch.getCall(3).args;
+      assert.equal(action.type, at.TELEMETRY_PERFORMANCE_EVENT);
+      assert.equal(action.data.event, "DS_FEED_TOTAL_REQUEST_TIME");
+      assert.equal(action.data.value, 5000);
+      feed.loaded = true;
+    });
+  });
 });