Bug 1451152 - Record timing for merging, updating Places, and staging records in the bookmarks mirror. r=tcsc
authorKit Cambridge <kit@yakshaving.ninja>
Wed, 18 Apr 2018 16:20:22 -0700
changeset 468039 72c16dae1e7f849b431801db533811c41f0220bd
parent 468038 16d084813aa7b8c24a42c08279b8ece88ec3ad57
child 468040 d42b55d603032606bc40ae6b24a0aa27e6d30c72
push id9165
push userasasaki@mozilla.com
push dateThu, 26 Apr 2018 21:04:54 +0000
treeherdermozilla-beta@064c3804de2e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerstcsc
bugs1451152
milestone61.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 1451152 - Record timing for merging, updating Places, and staging records in the bookmarks mirror. r=tcsc MozReview-Commit-ID: IQk4Bmb4h7S
toolkit/components/places/SyncedBookmarksMirror.jsm
--- a/toolkit/components/places/SyncedBookmarksMirror.jsm
+++ b/toolkit/components/places/SyncedBookmarksMirror.jsm
@@ -184,19 +184,19 @@ class SyncedBookmarksMirror {
           await attachAndInitMirrorDatabase(db, path);
         } else {
           MirrorLog.error("Unrecoverable error attaching mirror to Places", ex);
           throw ex;
         }
       }
       try {
         let info = await OS.File.stat(path);
-        let fileSize = Math.floor(info.size / 1024);
+        let size = Math.floor(info.size / 1024);
         options.recordTelemetryEvent("mirror", "open", "success",
-                                     { size: fileSize.toString(10) });
+                                     normalizeExtraTelemetryFields({ size }));
       } catch (ex) {
         MirrorLog.warn("Error recording stats for mirror database size", ex);
       }
     } catch (ex) {
       options.recordTelemetryEvent("mirror", "open", "error",
                                    { why: whyFailed });
       await db.close();
       throw ex;
@@ -371,25 +371,18 @@ class SyncedBookmarksMirror {
           }
         }
       ));
     } finally {
       for (let { method, value, extra } of extraTelemetryEvents) {
         this.recordTelemetryEvent("mirror", method, value, extra);
       }
       for (let kind in ignoreCounts) {
-        let reasons = ignoreCounts[kind];
-        let extra = {};
-        for (let reason in reasons) {
-          let count = reasons[reason];
-          if (count > 0) {
-            extra[reason] = String(count);
-          }
-        }
-        if (!ObjectUtils.isEmpty(extra)) {
+        let extra = normalizeExtraTelemetryFields(ignoreCounts[kind]);
+        if (extra) {
           this.recordTelemetryEvent("mirror", "ignore", kind, extra);
         }
       }
     }
   }
 
   /**
    * Builds a complete merged tree from the local and remote trees, resolves
@@ -425,77 +418,110 @@ class SyncedBookmarksMirror {
     // since merging can take a while for large trees, and we don't want to
     // block shutdown. Since all new items are in the mirror, we'll just try
     // to merge again on the next sync.
     let { missingParents, missingChildren } = await this.fetchRemoteOrphans();
     if (missingParents.length) {
       MirrorLog.warn("Temporarily reparenting remote items with missing " +
                      "parents to unfiled", missingParents);
       this.recordTelemetryEvent("mirror", "orphans", "parents",
-                                { count: String(missingParents.length) });
+        normalizeExtraTelemetryFields({ count: missingParents.length }));
     }
     if (missingChildren.length) {
       MirrorLog.warn("Remote tree missing items", missingChildren);
       this.recordTelemetryEvent("mirror", "orphans", "children",
-                                { count: String(missingChildren.length) });
+        normalizeExtraTelemetryFields({ count: missingChildren.length }));
     }
 
     let { missingLocal, missingRemote, wrongSyncStatus } =
       await this.fetchInconsistencies();
     if (missingLocal.length) {
       MirrorLog.warn("Remote tree has merged items that don't exist locally",
                      missingLocal);
       this.recordTelemetryEvent("mirror", "inconsistencies", "local",
-                                { count: String(missingLocal.length) });
+        normalizeExtraTelemetryFields({ count: missingLocal.length }));
     }
     if (missingRemote.length) {
       MirrorLog.warn("Local tree has synced items that don't exist remotely",
                      missingRemote);
       this.recordTelemetryEvent("mirror", "inconsistencies", "remote",
-                                { count: String(missingRemote.length) });
+        normalizeExtraTelemetryFields({ count: missingRemote.length }));
     }
     if (wrongSyncStatus.length) {
       MirrorLog.warn("Local tree has wrong sync statuses for items that " +
                      "exist remotely", wrongSyncStatus);
       this.recordTelemetryEvent("mirror", "inconsistencies", "syncStatus",
-                                { count: String(wrongSyncStatus.length) });
+        normalizeExtraTelemetryFields({ count: wrongSyncStatus.length }));
     }
 
+    let applyStats = {};
+
     // It's safe to build the remote tree outside the transaction because
     // `fetchRemoteTree` doesn't join to Places, only Sync writes to the
     // mirror, and we're holding the Sync lock at this point.
     MirrorLog.debug("Building remote tree from mirror");
-    let remoteTree = await this.fetchRemoteTree(remoteTimeSeconds);
+    let { result: remoteTree, time: remoteTreeTiming } = await withTiming(
+      "Fetch remote tree",
+      () => this.fetchRemoteTree(remoteTimeSeconds)
+    );
+    applyStats.remoteTree = { time: remoteTreeTiming,
+                              count: remoteTree.guidCount };
     if (MirrorLog.level <= Log.Level.Trace) {
       MirrorLog.trace("Built remote tree from mirror\n" +
                       remoteTree.toASCIITreeString());
     }
 
     let observersToNotify = new BookmarkObserverRecorder(this.db);
 
     let changeRecords = await this.db.executeTransaction(async () => {
       MirrorLog.debug("Building local tree from Places");
-      let localTree = await this.fetchLocalTree(localTimeSeconds);
+      let { result: localTree, time: localTreeTiming } = await withTiming(
+        "Fetch local tree",
+        () => this.fetchLocalTree(localTimeSeconds)
+      );
+      applyStats.localTree = { time: localTreeTiming,
+                               count: localTree.guidCount };
       if (MirrorLog.level <= Log.Level.Trace) {
         MirrorLog.trace("Built local tree from Places\n" +
                         localTree.toASCIITreeString());
       }
 
       MirrorLog.debug("Fetching content info for new mirror items");
-      let newRemoteContents = await this.fetchNewRemoteContents();
+      let {
+        result: newRemoteContents,
+        time: remoteContentsTiming,
+      } = await withTiming(
+        "Fetch new remote contents",
+        () => this.fetchNewRemoteContents()
+      );
+      applyStats.remoteContents = { time: remoteContentsTiming,
+                                    count: newRemoteContents.size };
 
       MirrorLog.debug("Fetching content info for new Places items");
-      let newLocalContents = await this.fetchNewLocalContents();
+      let {
+        result: newLocalContents,
+        time: localContentsTiming,
+      } = await withTiming(
+        "Fetch new local contents",
+        () => this.fetchNewLocalContents()
+      );
+      applyStats.localContents = { time: localContentsTiming,
+                                   count: newLocalContents.size };
 
       MirrorLog.debug("Building complete merged tree");
       let merger = new BookmarkMerger(localTree, newLocalContents,
                                       remoteTree, newRemoteContents);
       let mergedRoot;
       try {
-        mergedRoot = await merger.merge();
+        let time;
+        ({ result: mergedRoot, time } = await withTiming(
+          "Build merged tree",
+          () => merger.merge()
+        ));
+        applyStats.merge = { time };
       } finally {
         for (let { value, extra } of merger.summarizeTelemetryEvents()) {
           this.recordTelemetryEvent("mirror", "merge", value, extra);
         }
       }
 
       if (MirrorLog.level <= Log.Level.Trace) {
         MirrorLog.trace([
@@ -517,33 +543,43 @@ class SyncedBookmarksMirror {
           "Merged tree doesn't mention all items from remote tree");
       }
 
       MirrorLog.debug("Applying merged tree");
       let localDeletions = Array.from(merger.deleteLocally).map(guid =>
         ({ guid, level: localTree.levelForGuid(guid) })
       );
       let remoteDeletions = Array.from(merger.deleteRemotely);
-      await this.updateLocalItemsInPlaces(mergedRoot, localDeletions,
-                                          remoteDeletions);
+      let { time: updateTiming } = await withTiming(
+        "Apply merged tree",
+        () => this.updateLocalItemsInPlaces(mergedRoot, localDeletions,
+                                            remoteDeletions)
+      );
+      applyStats.update = { time: updateTiming };
 
       // At this point, the database is consistent, and we can fetch info to
       // pass to observers. Note that we can't fetch observer info in the
       // triggers above, because the structure might not be complete yet. An
       // incomplete structure might cause us to miss or record wrong parents and
       // positions.
 
       MirrorLog.debug("Recording observer notifications");
       await this.noteObserverChanges(observersToNotify);
 
-      MirrorLog.debug("Staging locally changed items for upload");
-      await this.stageItemsToUpload(weakUpload);
-
-      MirrorLog.debug("Fetching records for local items to upload");
-      let changeRecords = await this.fetchLocalChangeRecords();
+      let {
+        result: changeRecords,
+        time: stageTiming,
+      } = await withTiming("Stage outgoing items", async () => {
+        MirrorLog.debug("Staging locally changed items for upload");
+        await this.stageItemsToUpload(weakUpload);
+
+        MirrorLog.debug("Fetching records for local items to upload");
+        return this.fetchLocalChangeRecords();
+      });
+      applyStats.stage = { time: stageTiming };
 
       await this.db.execute(`DELETE FROM mergeStates`);
       await this.db.execute(`DELETE FROM itemsAdded`);
       await this.db.execute(`DELETE FROM guidsChanged`);
       await this.db.execute(`DELETE FROM itemsChanged`);
       await this.db.execute(`DELETE FROM itemsRemoved`);
       await this.db.execute(`DELETE FROM itemsMoved`);
       await this.db.execute(`DELETE FROM annosChanged`);
@@ -555,16 +591,23 @@ class SyncedBookmarksMirror {
 
     MirrorLog.debug("Replaying recorded observer notifications");
     try {
       await observersToNotify.notifyAll();
     } catch (ex) {
       MirrorLog.error("Error notifying Places observers", ex);
     }
 
+    for (let value in applyStats) {
+      let extra = normalizeExtraTelemetryFields(applyStats[value]);
+      if (extra) {
+        this.recordTelemetryEvent("mirror", "apply", value, extra);
+      }
+    }
+
     return changeRecords;
   }
 
   /**
    * Discards the mirror contents. This is called when the user is node
    * reassigned, disables the bookmarks engine, or signs out.
    */
   async reset() {
@@ -995,17 +1038,16 @@ class SyncedBookmarksMirror {
    *
    * @param  {Number} remoteTimeSeconds
    *         The current server time, in seconds.
    * @return {BookmarkTree}
    *         The remote bookmark tree.
    */
   async fetchRemoteTree(remoteTimeSeconds) {
     let remoteTree = new BookmarkTree(BookmarkNode.root());
-    let startTime = Cu.now();
 
     // First, build a flat mapping of parents to children. The `LEFT JOIN`
     // includes items orphaned by an interrupted upload on another device.
     // We keep the orphans in "unfiled" until the other device returns and
     // uploads the missing parent.
     // Note that we avoid returning orphaned queries here - there's a really
     // good chance that orphaned queries are actually left-pane queries with
     // the left-pane root missing.
@@ -1053,36 +1095,29 @@ class SyncedBookmarksMirror {
       WHERE isDeleted AND
             needsMerge`);
 
     for await (let row of yieldingIterator(tombstoneRows)) {
       let guid = row.getResultByName("guid");
       remoteTree.noteDeleted(guid);
     }
 
-    let elapsedTime = Cu.now() - startTime;
-    let totalRows = itemRows.length + tombstoneRows.length;
-    this.recordTelemetryEvent("mirror", "fetch", "remoteTree",
-                              { time: String(elapsedTime),
-                                count: String(totalRows) });
-
     return remoteTree;
   }
 
   /**
    * Fetches content info for all items in the mirror that changed since the
    * last sync and don't exist locally.
    *
    * @return {Map.<String, BookmarkContent>}
    *         Changed items in the mirror that don't exist in Places, keyed by
    *         their GUIDs.
    */
   async fetchNewRemoteContents() {
     let newRemoteContents = new Map();
-    let startTime = Cu.now();
 
     let rows = await this.db.execute(`
       SELECT v.guid, IFNULL(v.title, "") AS title, u.url, v.smartBookmarkName,
              IFNULL(s.position, -1) AS position
       FROM items v
       LEFT JOIN urls u ON u.id = v.urlId
       LEFT JOIN structure s ON s.guid = v.guid
       LEFT JOIN moz_bookmarks b ON b.guid = v.guid
@@ -1094,36 +1129,30 @@ class SyncedBookmarksMirror {
         rootGuid: PlacesUtils.bookmarks.rootGuid });
 
     for await (let row of yieldingIterator(rows)) {
       let guid = row.getResultByName("guid");
       let content = BookmarkContent.fromRow(row);
       newRemoteContents.set(guid, content);
     }
 
-    let elapsedTime = Cu.now() - startTime;
-    this.recordTelemetryEvent("mirror", "fetch", "newRemoteContents",
-                              { time: String(elapsedTime),
-                                count: String(rows.length) });
-
     return newRemoteContents;
   }
 
   /**
    * Builds a fully rooted, consistent tree from the items and tombstones in
    * Places.
    *
    * @param  {Number} localTimeSeconds
    *         The current local time, in seconds.
    * @return {BookmarkTree}
    *         The local bookmark tree.
    */
   async fetchLocalTree(localTimeSeconds) {
     let localTree = new BookmarkTree(BookmarkNode.root());
-    let startTime = Cu.now();
 
     // This unsightly query collects all descendants and maps their Places types
     // to the Sync record kinds. We start with the roots, and work our way down.
     // The list of roots in `syncedItems` should be updated if we add new
     // syncable roots to Places.
     let itemRows = await this.db.execute(`
       WITH RECURSIVE
       syncedItems(id, level) AS (
@@ -1176,37 +1205,30 @@ class SyncedBookmarksMirror {
     let tombstoneRows = await this.db.execute(`
       SELECT guid FROM moz_bookmarks_deleted`);
 
     for await (let row of yieldingIterator(tombstoneRows)) {
       let guid = row.getResultByName("guid");
       localTree.noteDeleted(guid);
     }
 
-    let elapsedTime = Cu.now() - startTime;
-    let totalRows = itemRows.length + tombstoneRows.length;
-    this.recordTelemetryEvent("mirror", "fetch", "localTree",
-                              { time: String(elapsedTime),
-                                count: String(totalRows) });
-
     return localTree;
   }
 
   /**
    * Fetches content info for all NEW and UNKNOWN local items that don't exist
    * in the mirror. We'll try to dedupe them to changed items with similar
    * contents and different GUIDs in the mirror.
    *
    * @return {Map.<String, BookmarkContent>}
    *         New items in Places that don't exist in the mirror, keyed by their
    *         GUIDs.
    */
   async fetchNewLocalContents() {
     let newLocalContents = new Map();
-    let startTime = Cu.now();
 
     let rows = await this.db.execute(`
       SELECT b.guid, IFNULL(b.title, "") AS title, h.url,
              (SELECT a.content FROM moz_items_annos a
               JOIN moz_anno_attributes n ON n.id = a.anno_attribute_id
               WHERE a.item_id = b.id AND
                     n.name = :smartBookmarkAnno) AS smartBookmarkName,
              b.position
@@ -1222,21 +1244,16 @@ class SyncedBookmarksMirror {
         syncStatus: PlacesUtils.bookmarks.SYNC_STATUS.NORMAL });
 
     for await (let row of yieldingIterator(rows)) {
       let guid = row.getResultByName("guid");
       let content = BookmarkContent.fromRow(row);
       newLocalContents.set(guid, content);
     }
 
-    let elapsedTime = Cu.now() - startTime;
-    this.recordTelemetryEvent("mirror", "fetch", "newLocalContents",
-                              { time: String(elapsedTime),
-                                count: String(rows.length) });
-
     return newLocalContents;
   }
 
   /**
    * Builds a temporary table with the merge states of all nodes in the merged
    * tree and updates Places to match the merged tree.
    *
    * Conceptually, we examine the merge state of each item, and either keep the
@@ -1904,16 +1921,38 @@ SyncedBookmarksMirror.ConsistencyError =
  */
 class DatabaseCorruptError extends Error {
   constructor(message) {
     super(message);
     this.name = "DatabaseCorruptError";
   }
 }
 
+// Converts extra integer fields to strings, and rounds timings to nanosecond
+// precision.
+function normalizeExtraTelemetryFields(extra) {
+  let result = {};
+  for (let key in extra) {
+    let value = extra[key];
+    let type = typeof value;
+    if (type == "string") {
+      result[key] = value;
+    } else if (type == "number") {
+      if (value > 0) {
+        result[key] = Number.isInteger(value) ? value.toString(10) :
+                      value.toFixed(3);
+      }
+    } else if (type != "undefined") {
+      throw new TypeError(`Invalid type ${
+        type} for extra telemetry field ${key}`);
+    }
+  }
+  return ObjectUtils.isEmpty(result) ? undefined : result;
+}
+
 // Indicates if the mirror should be replaced because the database file is
 // corrupt.
 function isDatabaseCorrupt(error) {
   if (error instanceof DatabaseCorruptError) {
     return true;
   }
   if (error.errors) {
     return error.errors.some(error =>
@@ -2739,16 +2778,27 @@ async function inflateTree(tree, pseudoT
     for (let node of nodes) {
       await maybeYield();
       tree.insert(parentGuid, node);
       await inflateTree(tree, pseudoTree, node.guid);
     }
   }
 }
 
+// Executes a function and returns a `{ result, time }` tuple, where `result` is
+// the function's return value, and `time` is the time taken to execute the
+// function.
+async function withTiming(name, func) {
+  let startTime = Cu.now();
+  let result = await func();
+  let elapsedTime = Cu.now() - startTime;
+  MirrorLog.debug(`${name} took ${elapsedTime.toFixed(3)}ms`);
+  return { result, time: elapsedTime };
+}
+
 /**
  * Content info for an item in the local or remote tree. This is used to dedupe
  * NEW local items to remote items that don't exist locally. See `makeDupeKey`
  * for how we determine if two items are dupes.
  */
 class BookmarkContent {
   constructor(title, urlHref, smartBookmarkName, position) {
     this.title = title;
@@ -3108,16 +3158,20 @@ class BookmarkTree {
     this.byGuid = new Map();
     this.infosByNode = new WeakMap();
     this.deletedGuids = new Set();
 
     this.root = root;
     this.byGuid.set(this.root.guid, this.root);
   }
 
+  get guidCount() {
+    return this.byGuid.size + this.deletedGuids.size;
+  }
+
   isDeleted(guid) {
     return this.deletedGuids.has(guid);
   }
 
   nodeForGuid(guid) {
     return this.byGuid.get(guid);
   }
 
@@ -3388,27 +3442,23 @@ class BookmarkMerger {
     };
     this.dupeCount = 0;
     this.extraTelemetryEvents = [];
   }
 
   summarizeTelemetryEvents() {
     let events = [...this.extraTelemetryEvents];
     if (this.dupeCount > 0) {
-      events.push({ value: "dupes",
-                    extra: { count: String(this.dupeCount) } });
+      events.push({
+        value: "dupes",
+        extra: normalizeExtraTelemetryFields({ count: this.dupeCount }),
+      });
     }
-    let structureExtra = {};
-    for (let key in this.structureCounts) {
-      let count = this.structureCounts[key];
-      if (count > 0) {
-        structureExtra[key] = String(count);
-      }
-    }
-    if (!ObjectUtils.isEmpty(structureExtra)) {
+    let structureExtra = normalizeExtraTelemetryFields(this.structureCounts);
+    if (structureExtra) {
       events.push({ value: "structure", extra: structureExtra });
     }
     return events;
   }
 
   async merge() {
     let mergedRoot = new MergedBookmarkNode(PlacesUtils.bookmarks.rootGuid,
       BookmarkNode.root(), null, BookmarkMergeState.local);