Bug 1515081 - Reimplement autocomplete result timing telemetry for the new quantumbar. r=mak
authorMark Banner <standard8@mozilla.com>
Wed, 09 Jan 2019 15:11:49 +0000
changeset 510159 068f7beef2c8bf034eb11e4de744644a615ca463
parent 510158 5747fe4edb8ab19b37598d76fb7577b4320ade0f
child 510160 52bc1477d801eebf61511e0071edc949dcdc1a36
push id10547
push userffxbld-merge
push dateMon, 21 Jan 2019 13:03:58 +0000
treeherdermozilla-beta@24ec1916bffe [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmak
bugs1515081
milestone66.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1515081 - Reimplement autocomplete result timing telemetry for the new quantumbar. r=mak Differential Revision: https://phabricator.services.mozilla.com/D15818
browser/components/urlbar/UrlbarController.jsm
browser/components/urlbar/UrlbarProviderUnifiedComplete.jsm
browser/components/urlbar/tests/unit/test_UrlbarController_telemetry.js
browser/components/urlbar/tests/unit/test_UrlbarController_unit.js
browser/components/urlbar/tests/unit/xpcshell.ini
toolkit/components/places/UnifiedComplete.js
toolkit/components/places/tests/unit/test_telemetry.js
--- a/browser/components/urlbar/UrlbarController.jsm
+++ b/browser/components/urlbar/UrlbarController.jsm
@@ -9,16 +9,19 @@ var EXPORTED_SYMBOLS = ["QueryContext", 
 ChromeUtils.import("resource://gre/modules/XPCOMUtils.jsm");
 XPCOMUtils.defineLazyModuleGetters(this, {
   AppConstants: "resource://gre/modules/AppConstants.jsm",
   // BrowserUsageTelemetry: "resource:///modules/BrowserUsageTelemetry.jsm",
   UrlbarPrefs: "resource:///modules/UrlbarPrefs.jsm",
   UrlbarProvidersManager: "resource:///modules/UrlbarProvidersManager.jsm",
 });
 
+const TELEMETRY_1ST_RESULT = "PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS";
+const TELEMETRY_6_FIRST_RESULTS = "PLACES_AUTOCOMPLETE_6_FIRST_RESULTS_TIME_MS";
+
 /**
  * The address bar controller handles queries from the address bar, obtains
  * results and returns them to the UI for display.
  *
  * Listeners may be added to listen for the results. They must support the
  * following methods which may be called when a query is run:
  *
  * - onQueryStarted(queryContext)
@@ -83,41 +86,59 @@ class UrlbarController {
     // Cancel any running query.
     if (this._lastQueryContext) {
       this.cancelQuery(this._lastQueryContext);
     }
     this._lastQueryContext = queryContext;
 
     queryContext.autoFill = UrlbarPrefs.get("autoFill");
 
+    queryContext.lastTelemetryResultCount = 0;
+    TelemetryStopwatch.start(TELEMETRY_1ST_RESULT, queryContext);
+    TelemetryStopwatch.start(TELEMETRY_6_FIRST_RESULTS, queryContext);
+
     this._notify("onQueryStarted", queryContext);
     await this.manager.startQuery(queryContext, this);
     this._notify("onQueryFinished", queryContext);
   }
 
   /**
    * Cancels an in-progress query. Note, queries may continue running if they
    * can't be canceled.
    *
    * @param {QueryContext} queryContext The query details.
    */
   cancelQuery(queryContext) {
     if (queryContext === this._lastQueryContext) {
       delete this._lastQueryContext;
     }
+
+    TelemetryStopwatch.cancel(TELEMETRY_1ST_RESULT, queryContext);
+    TelemetryStopwatch.cancel(TELEMETRY_6_FIRST_RESULTS, queryContext);
+
     this.manager.cancelQuery(queryContext);
     this._notify("onQueryCancelled", queryContext);
   }
 
   /**
    * Receives results from a query.
    *
    * @param {QueryContext} queryContext The query details.
    */
   receiveResults(queryContext) {
+    if (queryContext.lastTelemetryResultCount < 1 &&
+        queryContext.results.length >= 1) {
+      TelemetryStopwatch.finish(TELEMETRY_1ST_RESULT, queryContext);
+    }
+    if (queryContext.lastTelemetryResultCount < 6 &&
+        queryContext.results.length >= 6) {
+      TelemetryStopwatch.finish(TELEMETRY_6_FIRST_RESULTS, queryContext);
+    }
+    queryContext.lastTelemetryResultCount = queryContext.results.length;
+
     this._notify("onQueryResults", queryContext);
   }
 
   /**
    * Adds a listener for query actions and results.
    *
    * @param {object} listener The listener to add.
    * @throws {TypeError} Throws if the listener is not an object.
--- a/browser/components/urlbar/UrlbarProviderUnifiedComplete.jsm
+++ b/browser/components/urlbar/UrlbarProviderUnifiedComplete.jsm
@@ -91,16 +91,19 @@ class ProviderUnifiedComplete extends Ur
     //    private browsing mode. ()
     //  * "private-window": the search is taking place in a private window.
     //  * "user-context-id:#": the userContextId to use.
     let params = ["enable-actions"];
     params.push(`max-results:${queryContext.maxResults}`);
     // This is necessary because we insert matches one by one, thus we don't
     // want UnifiedComplete to reuse results.
     params.push(`insert-method:${UrlbarUtils.INSERTMETHOD.APPEND}`);
+    // The Quantum Bar has its own telemetry measurement, thus disable old
+    // telemetry logged by UnifiedComplete.
+    params.push("disable-telemetry");
     if (queryContext.isPrivate) {
       params.push("private-window");
       if (!PrivateBrowsingUtils.permanentPrivateBrowsing) {
         params.push("disable-private-actions");
       }
     }
     if (queryContext.userContextId) {
       params.push(`user-context-id:${queryContext.userContextId}}`);
new file mode 100644
--- /dev/null
+++ b/browser/components/urlbar/tests/unit/test_UrlbarController_telemetry.js
@@ -0,0 +1,193 @@
+/* Any copyright is dedicated to the Public Domain.
+   http://creativecommons.org/publicdomain/zero/1.0/ */
+
+/**
+ * These tests unit test the functionality of UrlbarController by stubbing out the
+ * model and providing stubs to be called.
+ */
+
+"use strict";
+
+const TEST_URL = "http://example.com";
+const MATCH = new UrlbarMatch(UrlbarUtils.MATCH_TYPE.TAB_SWITCH,
+                              UrlbarUtils.MATCH_SOURCE.TABS,
+                              { url: TEST_URL });
+const TELEMETRY_1ST_RESULT = "PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS";
+const TELEMETRY_6_FIRST_RESULTS = "PLACES_AUTOCOMPLETE_6_FIRST_RESULTS_TIME_MS";
+
+let controller;
+let firstHistogram;
+let sixthHistogram;
+
+/**
+ * A delayed test provider, allowing the query to be delayed for an amount of time.
+ */
+class DelayedProvider extends UrlbarProvider {
+  constructor() {
+    super();
+    this._name = "TestProvider" + Math.floor(Math.random() * 100000);
+  }
+  get name() {
+    return this._name;
+  }
+  get type() {
+    return UrlbarUtils.PROVIDER_TYPE.PROFILE;
+  }
+  get sources() {
+    return [UrlbarUtils.MATCH_SOURCE.TABS];
+  }
+  async startQuery(context, add) {
+    Assert.ok(context, "context is passed-in");
+    Assert.equal(typeof add, "function", "add is a callback");
+    this._context = context;
+    this._add = add;
+  }
+  cancelQuery(context) {
+    Assert.ok(false, "cancelQuery should not be called");
+  }
+  addResults(matches) {
+    for (const match of matches) {
+      this._add(this, match);
+    }
+  }
+}
+
+/**
+ * Returns the number of reports sent recorded within the histogram results.
+ *
+ * @param {object} results a snapshot of histogram results to check.
+ * @returns {number} The count of reports recorded in the histogram.
+ */
+function getHistogramReportsCount(results) {
+  let sum = 0;
+  for (let [, value] of Object.entries(results.values)) {
+    sum += value;
+  }
+  return sum;
+}
+
+add_task(function setup() {
+  controller = new UrlbarController({
+    browserWindow: {
+      location: {
+        href: AppConstants.BROWSER_CHROME_URL,
+      },
+    },
+  });
+
+  firstHistogram = Services.telemetry.getHistogramById(TELEMETRY_1ST_RESULT);
+  sixthHistogram = Services.telemetry.getHistogramById(TELEMETRY_6_FIRST_RESULTS);
+});
+
+add_task(async function test_n_autocomplete_cancel() {
+  firstHistogram.clear();
+  sixthHistogram.clear();
+
+  let providerCanceledDeferred = PromiseUtils.defer();
+  let provider = new TestProvider([], providerCanceledDeferred.resolve);
+  UrlbarProvidersManager.registerProvider(provider);
+  const context = createContext(TEST_URL, {providers: [provider.name]});
+
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_1ST_RESULT, context),
+    "Should not have started first result stopwatch");
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_6_FIRST_RESULTS, context),
+    "Should not have started first 6 results stopwatch");
+
+  await controller.startQuery(context);
+
+  Assert.ok(TelemetryStopwatch.running(TELEMETRY_1ST_RESULT, context),
+    "Should have started first result stopwatch");
+  Assert.ok(TelemetryStopwatch.running(TELEMETRY_6_FIRST_RESULTS, context),
+    "Should have started first 6 results stopwatch");
+
+  controller.cancelQuery(context);
+
+  await providerCanceledDeferred.promise;
+
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_1ST_RESULT, context),
+    "Should have canceled first result stopwatch");
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_6_FIRST_RESULTS, context),
+    "Should have canceled first 6 results stopwatch");
+
+  let results = firstHistogram.snapshot();
+  Assert.equal(results.sum, 0, "Should not have recorded any times (first result)");
+  results = sixthHistogram.snapshot();
+  Assert.equal(results.sum, 0, "Should not have recorded any times (first 6 results)");
+});
+
+add_task(async function test_n_autocomplete_results() {
+  firstHistogram.clear();
+  sixthHistogram.clear();
+
+  let provider = new DelayedProvider();
+  UrlbarProvidersManager.registerProvider(provider);
+  const context = createContext(TEST_URL, {providers: [provider.name]});
+
+  let resultsPromise = promiseControllerNotification(controller, "onQueryResults");
+
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_1ST_RESULT, context),
+    "Should not have started first result stopwatch");
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_6_FIRST_RESULTS, context),
+    "Should not have started first 6 results stopwatch");
+
+  await controller.startQuery(context);
+
+  Assert.ok(TelemetryStopwatch.running(TELEMETRY_1ST_RESULT, context),
+    "Should have started first result stopwatch");
+  Assert.ok(TelemetryStopwatch.running(TELEMETRY_6_FIRST_RESULTS, context),
+    "Should have started first 6 results stopwatch");
+
+  provider.addResults([MATCH]);
+  await resultsPromise;
+
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_1ST_RESULT, context),
+    "Should have stopped the first stopwatch");
+  Assert.ok(TelemetryStopwatch.running(TELEMETRY_6_FIRST_RESULTS, context),
+    "Should have kept the first 6 results stopwatch running");
+
+  let firstResults = firstHistogram.snapshot();
+  let first6Results = sixthHistogram.snapshot();
+  Assert.equal(getHistogramReportsCount(firstResults), 1,
+    "Should have recorded one time for the first result");
+  Assert.equal(getHistogramReportsCount(first6Results), 0,
+    "Should not have recorded any times (first 6 results)");
+
+  // Now add 5 more results, so that the first 6 results is triggered.
+  for (let i = 0; i < 5; i++) {
+    resultsPromise = promiseControllerNotification(controller, "onQueryResults");
+    provider.addResults([
+      new UrlbarMatch(UrlbarUtils.MATCH_TYPE.TAB_SWITCH,
+                      UrlbarUtils.MATCH_SOURCE.TABS,
+                      { url: TEST_URL + "/i" }),
+    ]);
+    await resultsPromise;
+  }
+
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_1ST_RESULT, context),
+    "Should have stopped the first stopwatch");
+  Assert.ok(!TelemetryStopwatch.running(TELEMETRY_6_FIRST_RESULTS, context),
+    "Should have stopped the first 6 results stopwatch");
+
+  let updatedResults = firstHistogram.snapshot();
+  let updated6Results = sixthHistogram.snapshot();
+  Assert.deepEqual(updatedResults, firstResults,
+    "Should not have changed the histogram for the first result");
+  Assert.equal(getHistogramReportsCount(updated6Results), 1,
+    "Should have recorded one time for the first 6 results");
+
+  // Add one more, to check neither are updated.
+  resultsPromise = promiseControllerNotification(controller, "onQueryResults");
+  provider.addResults([
+    new UrlbarMatch(UrlbarUtils.MATCH_TYPE.TAB_SWITCH,
+                    UrlbarUtils.MATCH_SOURCE.TABS,
+                    { url: TEST_URL + "/6" }),
+  ]);
+  await resultsPromise;
+
+  let secondUpdateResults = firstHistogram.snapshot();
+  let secondUpdate6Results = sixthHistogram.snapshot();
+  Assert.deepEqual(secondUpdateResults, firstResults,
+    "Should not have changed the histogram for the first result");
+  Assert.equal(getHistogramReportsCount(secondUpdate6Results), 1,
+    "Should not have changed the histogram for the first 6 results");
+});
--- a/browser/components/urlbar/tests/unit/test_UrlbarController_unit.js
+++ b/browser/components/urlbar/tests/unit/test_UrlbarController_unit.js
@@ -187,30 +187,31 @@ add_task(function test_cancel_query() {
   Assert.deepEqual(generalListener.onQueryCancelled.args[0], [context],
     "Should have called onQueryCancelled with the context");
 
   sandbox.resetHistory();
 });
 
 add_task(function test_receiveResults() {
   const context = createContext();
+  context.results = [];
   controller.receiveResults(context);
 
   Assert.equal(generalListener.onQueryResults.callCount, 1,
     "Should have called onQueryResults for the listener");
   Assert.deepEqual(generalListener.onQueryResults.args[0], [context],
     "Should have called onQueryResults with the context");
 
   sandbox.resetHistory();
 });
 
 add_task(function test_autocomplete_enabled() {
   const context = createContext();
+  context.results = [];
   controller.receiveResults(context);
 
   Assert.equal(generalListener.onQueryResults.callCount, 1,
     "Should have called onQueryResults for the listener");
   Assert.deepEqual(generalListener.onQueryResults.args[0], [context],
     "Should have called onQueryResults with the context");
 
   sandbox.resetHistory();
 });
-
--- a/browser/components/urlbar/tests/unit/xpcshell.ini
+++ b/browser/components/urlbar/tests/unit/xpcshell.ini
@@ -8,11 +8,12 @@ support-files =
 [test_providerOpenTabs.js]
 [test_providersManager.js]
 [test_providerUnifiedComplete.js]
 [test_providersManager_filtering.js]
 [test_providersManager_maxResults.js]
 [test_QueryContext.js]
 [test_tokenizer.js]
 [test_UrlbarController_unit.js]
+[test_UrlbarController_telemetry.js]
 [test_UrlbarController_integration.js]
 [test_UrlbarUtils_addToUrlbarHistory.js]
 [test_UrlbarUtils_getShortcutOrURIAndPostData.js]
--- a/toolkit/components/places/UnifiedComplete.js
+++ b/toolkit/components/places/UnifiedComplete.js
@@ -609,16 +609,17 @@ function Search(searchString, searchPara
   this._behavior = this._searchString ? UrlbarPrefs.get("defaultBehavior")
                                       : UrlbarPrefs.get("emptySearchDefaultBehavior");
 
   let params = new Set(searchParam.split(" "));
   this._enableActions = params.has("enable-actions");
   this._disablePrivateActions = params.has("disable-private-actions");
   this._inPrivateWindow = params.has("private-window");
   this._prohibitAutoFill = params.has("prohibit-autofill");
+  this._disableTelemetry = params.has("disable-telemetry");
 
   // Extract the max-results param.
   let maxResults = searchParam.match(REGEXP_MAX_RESULTS);
   this._maxResults = maxResults ? parseInt(maxResults[1])
                                 : UrlbarPrefs.get("maxRichResults");
 
   // Extract the user-context-id param.
   let userContextId = searchParam.match(REGEXP_USER_CONTEXT_ID);
@@ -851,18 +852,20 @@ Search.prototype = {
     // Used by stop() to interrupt an eventual running statement.
     this.interrupt = () => {
       // Interrupt any ongoing statement to run the search sooner.
       if (!UrlbarProvidersManager.interruptLevel) {
         conn.interrupt();
       }
     };
 
-    TelemetryStopwatch.start(TELEMETRY_1ST_RESULT, this);
-    TelemetryStopwatch.start(TELEMETRY_6_FIRST_RESULTS, this);
+    if (!this._disableTelemetry) {
+      TelemetryStopwatch.start(TELEMETRY_1ST_RESULT, this);
+      TelemetryStopwatch.start(TELEMETRY_6_FIRST_RESULTS, this);
+    }
 
     // Since we call the synchronous parseSubmissionURL function later, we must
     // wait for the initialization of PlacesSearchAutocompleteProvider first.
     await PlacesSearchAutocompleteProvider.ensureInitialized();
     if (!this.pending)
       return;
 
     // For any given search, we run many queries/heuristics:
@@ -1929,20 +1932,22 @@ Search.prototype = {
                                match.value,
                                match.comment,
                                match.icon,
                                match.style,
                                match.finalCompleteValue);
     this._currentMatchCount++;
     this._counts[match.type]++;
 
-    if (this._currentMatchCount == 1)
-      TelemetryStopwatch.finish(TELEMETRY_1ST_RESULT, this);
-    if (this._currentMatchCount == 6)
-      TelemetryStopwatch.finish(TELEMETRY_6_FIRST_RESULTS, this);
+    if (!this._disableTelemetry) {
+      if (this._currentMatchCount == 1)
+        TelemetryStopwatch.finish(TELEMETRY_1ST_RESULT, this);
+      if (this._currentMatchCount == 6)
+        TelemetryStopwatch.finish(TELEMETRY_6_FIRST_RESULTS, this);
+    }
     this.notifyResult(true, match.type == UrlbarUtils.MATCH_GROUP.HEURISTIC);
   },
 
   _getInsertIndexForMatch(match) {
     // Check for duplicates and either discard (by returning -1) the duplicate
     // or suggest to replace the original match, in case the new one is more
     // specific (for example a Remote Tab wins over History, and a Switch to Tab
     // wins over a Remote Tab).
@@ -2680,18 +2685,20 @@ UnifiedComplete.prototype = {
   /**
    * Properly cleans up when searching is completed.
    *
    * @param notify [optional]
    *        Indicates if we should notify the AutoComplete listener about our
    *        results or not.
    */
   finishSearch(notify = false) {
-    TelemetryStopwatch.cancel(TELEMETRY_1ST_RESULT, this);
-    TelemetryStopwatch.cancel(TELEMETRY_6_FIRST_RESULTS, this);
+    if (!this._disableTelemetry) {
+      TelemetryStopwatch.cancel(TELEMETRY_1ST_RESULT, this);
+      TelemetryStopwatch.cancel(TELEMETRY_6_FIRST_RESULTS, this);
+    }
     // Clear state now to avoid race conditions, see below.
     let search = this._currentSearch;
     if (!search)
       return;
     this._lastLowResultsSearchSuggestion = search._lastLowResultsSearchSuggestion;
 
     if (!notify || !search.pending)
       return;
--- a/toolkit/components/places/tests/unit/test_telemetry.js
+++ b/toolkit/components/places/tests/unit/test_telemetry.js
@@ -12,17 +12,16 @@ var histograms = {
   PLACES_KEYWORDS_COUNT: val => Assert.equal(val, 1),
   PLACES_SORTED_BOOKMARKS_PERC: val => Assert.equal(val, 100),
   PLACES_TAGGED_BOOKMARKS_PERC: val => Assert.equal(val, 100),
   PLACES_DATABASE_FILESIZE_MB: val => Assert.ok(val > 0),
   PLACES_DATABASE_FAVICONS_FILESIZE_MB: val => Assert.ok(val > 0),
   PLACES_DATABASE_PAGESIZE_B: val => Assert.equal(val, 32768),
   PLACES_DATABASE_SIZE_PER_PAGE_B: val => Assert.ok(val > 0),
   PLACES_EXPIRATION_STEPS_TO_CLEAN2: val => Assert.ok(val > 1),
-  // PLACES_AUTOCOMPLETE_1ST_RESULT_TIME_MS:  val => do_check_true(val > 1),
   PLACES_IDLE_FRECENCY_DECAY_TIME_MS: val => Assert.ok(val >= 0),
   PLACES_IDLE_MAINTENANCE_TIME_MS: val => Assert.ok(val > 0),
   PLACES_ANNOS_BOOKMARKS_COUNT: val => Assert.equal(val, 1),
   PLACES_ANNOS_PAGES_COUNT: val => Assert.equal(val, 1),
   PLACES_MAINTENANCE_DAYSFROMLAST: val => Assert.ok(val >= 0),
 };
 
 /**
@@ -116,52 +115,16 @@ add_task(async function test_execute() {
       uri: NetUtil.newURI("http://" + i + ".moz.org/"),
       visitDate: newTimeInMicroseconds(),
     });
   }
   Services.prefs.setIntPref("places.history.expiration.max_pages", 0);
   await promiseForceExpirationStep(2);
   await promiseForceExpirationStep(2);
 
-  // Test autocomplete probes.
-  /*
-  // This is useful for manual testing by changing the minimum time for
-  // autocomplete telemetry to 0, but there is no way to artificially delay
-  // autocomplete by more than 50ms in a realiable way.
-  Services.prefs.setIntPref("browser.urlbar.search.sources", 3);
-  Services.prefs.setIntPref("browser.urlbar.default.behavior", 0);
-  function AutoCompleteInput(aSearches) {
-    this.searches = aSearches;
-  }
-  AutoCompleteInput.prototype = {
-    timeout: 10,
-    textValue: "",
-    searchParam: "",
-    popupOpen: false,
-    minResultsForPopup: 0,
-    invalidate: function() {},
-    disableAutoComplete: false,
-    completeDefaultIndex: false,
-    get popup() { return this; },
-    onSearchBegin: function() {},
-    onSearchComplete: function() {},
-    setSelectedIndex: function() {},
-    get searchCount() { return this.searches.length; },
-    getSearchAt: function(aIndex) { return this.searches[aIndex]; },
-    QueryInterface: ChromeUtils.generateQI([
-      Ci.nsIAutoCompleteInput,
-      Ci.nsIAutoCompletePopup,
-    ])
-  };
-  let controller = Cc["@mozilla.org/autocomplete/controller;1"].
-                   getService(Ci.nsIAutoCompleteController);
-  controller.input = new AutoCompleteInput(["unifiedcomplete"]);
-  controller.startSearch("moz");
-  */
-
   // Test idle probes.
   PlacesUtils.history.QueryInterface(Ci.nsIObserver)
                      .observe(null, "idle-daily", null);
   await PlacesDBUtils.maintenanceOnIdle();
 
   for (let histogramId in histograms) {
     info("checking histogram " + histogramId);
     let validate = histograms[histogramId];