Bug 1552621 - Include optional steps in Sync engine telemetry. r=tcsc…

…,tdsmith

Before this commit, we used event telemetry to record timing and counts
for the different steps of a bookmark merge (fetching the local tree,
new local contents, remote tree, and new remote contents; merging;
applying; fetching outgoing records; and notifying observers).

This has several limitations. We need to store all numbers as strings,
include a "flow ID" to tag events from the same merge, and collect
failure reasons twice. We also can't correlate these events to the
existing engine telemetry, meaning we can't see other stats for that
engine, or for the entire sync. Finally, we need to run separate
queries on these events for analysis, instead of extending our
existing engine dashboards.

This approach also feels like an abuse of event telemetry, so this
commit adds a "steps" field for each engine in the Sync ping. Each step
has a name, time taken, and additional named counts, like the number of
items in the tree, or merged structure stats.

Currently, only the `buffered-bookmarks` engine records these steps.

Differential Revision: https://phabricator.services.mozilla.com/D33411

--HG--
extra : moz-landing-system : lando

services/sync/modules/engines/bookmarks.js

@@ -1226,7 +1226,13 @@ BufferedBookmarksStore.prototype = {
         this.engine.service.recordTelemetryEvent(object, method, value,
                                                  extra);
       },
-      recordStepTelemetry() {},
+      recordStepTelemetry: (name, took, counts) => {
+        Observers.notify("weave:engine:sync:step", {
+          name,
+          took,
+          counts,
+        }, this.name);
+      },
       recordValidationTelemetry: (took, checked, problems) => {
         Observers.notify("weave:engine:validate:finish", {
           version: BUFFERED_BOOKMARK_VALIDATOR_VERSION,

services/sync/modules/telemetry.js

@@ -47,6 +47,7 @@ const TOPICS = [
   "weave:engine:sync:finish",
   "weave:engine:sync:error",
   "weave:engine:sync:applied",
+  "weave:engine:sync:step",
   "weave:engine:sync:uploaded",
   "weave:engine:validate:finish",
   "weave:engine:validate:error",
@@ -166,7 +167,7 @@ class EngineRecord {
   toJSON() {
     let result = { name: this.overrideTelemetryName || this.name };
     let properties = ["took", "status", "failureReason", "incoming", "outgoing",
-      "validation"];
+      "validation", "steps"];
     for (let property of properties) {
       result[property] = this[property];
     }
@@ -206,6 +207,26 @@ class EngineRecord {
     }
   }
 
+  recordStep(stepResult) {
+    let step = {
+      name: stepResult.name,
+    };
+    if (stepResult.took > 0) {
+      step.took = Math.round(stepResult.took);
+    }
+    if (stepResult.counts) {
+      let counts = stepResult.counts.filter(({count}) => count > 0);
+      if (counts.length) {
+        step.counts = counts;
+      }
+    }
+    if (this.steps) {
+      this.steps.push(step);
+    } else {
+      this.steps = [step];
+    }
+  }
+
   recordValidation(validationResult) {
     if (this.validation) {
       log.error(`Multiple validations occurred for engine ${this.name}!`);
@@ -390,6 +411,13 @@ class TelemetryRecord {
     this.currentEngine.recordApplied(counts);
   }
 
+  onEngineStep(engineName, step) {
+    if (this._shouldIgnoreEngine(engineName)) {
+      return;
+    }
+    this.currentEngine.recordStep(step);
+  }
+
   onEngineValidated(engineName, validationData) {
     if (this._shouldIgnoreEngine(engineName, false)) {
       return;
@@ -704,6 +732,12 @@ class SyncTelemetryImpl {
         }
         break;
 
+      case "weave:engine:sync:step":
+        if (this._checkCurrent(topic)) {
+          this.current.onEngineStep(data, subject);
+        }
+        break;
+
       case "weave:engine:sync:uploaded":
         if (this._checkCurrent(topic)) {
           this.current.onEngineUploaded(data, subject);

services/sync/tests/unit/sync_ping_schema.json

@@ -116,6 +116,11 @@
           "minItems": 1,
           "items": { "$ref": "#/definitions/outgoingBatch" }
         },
+        "steps": {
+          "type": "array",
+          "minItems": 1,
+          "$ref": "#/definitions/step"
+        },
         "validation": {
           "type": "object",
           "additionalProperties": false,
@@ -131,7 +136,7 @@
             "problems": {
               "type": "array",
               "minItems": 1,
-              "$ref": "#/definitions/validationProblem"
+              "$ref": "#/definitions/namedCount"
             }
           }
         }
@@ -213,7 +218,19 @@
         "code": { "type": "integer" }
       }
     },
-    "validationProblem": {
+    "step": {
+      "required": ["name"],
+      "properties": {
+        "name": { "type": "string" },
+        "took": { "type": "integer", "minimum": 1 },
+        "counts": {
+          "type": "array",
+          "minItems": 1,
+          "$ref": "#/definitions/namedCount"
+        }
+      }
+    },
+    "namedCount": {
       "required": ["name", "count"],
       "properties": {
         "name": { "type": "string" },

services/sync/tests/unit/test_bookmark_engine.js

@@ -215,6 +215,10 @@ add_bookmark_test(async function test_delete_invalid_roots_from_server(engine) {
           name: "parentChildDisagreements",
           count: 1,
         }], "Buffered engine should report parent-child disagreement");
+        deepEqual(engineData.steps.map(step => step.name), ["fetchLocalTree",
+          "fetchNewLocalContents", "fetchRemoteTree", "fetchNewRemoteContents",
+          "merge", "apply", "notifyObservers",
+          "fetchLocalChangeRecords"], "Buffered engine should report all merge steps");
       }
     } else {
       // The legacy engine doesn't report validation failures for this case,

toolkit/components/telemetry/docs/data/sync-ping.rst

@@ -79,6 +79,23 @@ Structure:
               // Optional, excluded if there were no errors
               failureReason: { ... }, // Same as above.
 
+              // Timings and counts for detailed steps that the engine reported
+              // as part of its sync. Optional; omitted if the engine didn't
+              // report any extra steps.
+              steps: {
+                name: <string>, // The step name.
+                took: <integer duration in milliseconds>, // Omitted if 0.
+                // Optional, extra named counts (e.g., number of items handled
+                // in this step). Omitted if the engine didn't report extra
+                // counts.
+                counts: [
+                  {
+                    name: <string>, // The counter name.
+                    count: <integer>, // The counter value.
+                  },
+                ],
+              },
+
               // Optional, excluded if it would be empty or if the engine cannot
               // or did not run validation on itself.
               validation: {