Bug 1433698 - Make trace logging for synced bookmark trees less noisy. r?markh draft
authorKit Cambridge <kit@yakshaving.ninja>
Sat, 27 Jan 2018 13:04:06 -0800
changeset 748165 832e01736768397cba00bb68b63cb651b5c21810
parent 748015 232dbd5acc3f2be2be59eddb3e7ef1d00d9111a0
child 748166 775ad0de8a3a6929f684343e8628176e73c9c73e
push id97076
push userbmo:kit@mozilla.com
push dateSun, 28 Jan 2018 21:11:54 +0000
reviewersmarkh
bugs1433698
milestone60.0a1
Bug 1433698 - Make trace logging for synced bookmark trees less noisy. r?markh MozReview-Commit-ID: 1MSxKdsgsIu
toolkit/components/places/SyncedBookmarksMirror.jsm
--- a/toolkit/components/places/SyncedBookmarksMirror.jsm
+++ b/toolkit/components/places/SyncedBookmarksMirror.jsm
@@ -329,42 +329,51 @@ class SyncedBookmarksMirror {
                                 { count: String(missingChildren.length) });
     }
 
     // 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);
-    MirrorLog.trace("Built remote tree from mirror", remoteTree);
+    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);
-      MirrorLog.trace("Built local tree from Places", localTree);
+      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();
 
       MirrorLog.debug("Fetching content info for new Places items");
       let newLocalContents = await this.fetchNewLocalContents();
 
       MirrorLog.debug("Building complete merged tree");
       let merger = new BookmarkMerger(localTree, newLocalContents,
                                       remoteTree, newRemoteContents);
       let mergedRoot = merger.merge();
       for (let { value, extra } of merger.telemetryEvents) {
         this.recordTelemetryEvent("mirror", "merge", value, extra);
       }
 
       if (MirrorLog.level <= Log.Level.Trace) {
-        let newTreeRoot = mergedRoot.toBookmarkNode();
-        MirrorLog.trace("Built new merged tree", newTreeRoot);
+        MirrorLog.trace([
+          "Built new merged tree",
+          mergedRoot.toASCIITreeString(),
+          ...merger.deletionsToStrings(),
+        ].join("\n"));
       }
 
       // The merged tree should know about all items mentioned in the local
       // and remote trees. Otherwise, it's incomplete, and we'll corrupt
       // Places or lose data on the server if we try to apply it.
       if (!merger.subsumes(localTree)) {
         throw new SyncedBookmarksMirror.ConsistencyError(
           "Merged tree doesn't mention all items from local tree");
@@ -2557,16 +2566,56 @@ class BookmarkMergeState {
   structure() {
     return this.newStructureNode ? BookmarkMergeState.TYPE.NEW : this.type;
   }
 
   // Returns the value state type: `LOCAL` or `REMOTE`.
   value() {
     return this.type;
   }
+
+  /**
+   * Returns a representation of the value ("V") and structure ("S") state
+   * for logging. "L" is "local", "R" is "remote", and "+" is "new". We use
+   * compact notation here to reduce noise in trace logs, which log the
+   * merge state of every node in the tree.
+   *
+   * @return {String}
+   */
+  toString() {
+    return `(${this.valueToString()}; ${this.structureToString()})`;
+  }
+
+  valueToString() {
+    switch (this.value()) {
+      case BookmarkMergeState.TYPE.LOCAL:
+        return "V: L";
+      case BookmarkMergeState.TYPE.REMOTE:
+        return "V: R";
+    }
+    return "V: ?";
+  }
+
+  structureToString() {
+    switch (this.structure()) {
+      case BookmarkMergeState.TYPE.LOCAL:
+        return "S: L";
+      case BookmarkMergeState.TYPE.REMOTE:
+        return "S: R";
+      case BookmarkMergeState.TYPE.NEW:
+        // We intentionally don't log the new structure node here, since
+        // the merger already does that.
+        return "S: +";
+    }
+    return "S: ?";
+  }
+
+  toJSON() {
+    return this.toString();
+  }
 }
 
 BookmarkMergeState.TYPE = {
   LOCAL: 1,
   REMOTE: 2,
   NEW: 3,
 };
 
@@ -2679,16 +2728,71 @@ class BookmarkNode {
   * descendants() {
     for (let node of this.children) {
       yield node;
       if (node.isFolder()) {
         yield* node.descendants();
       }
     }
   }
+
+  /**
+   * Generates a human-readable, ASCII art representation of the node and its
+   * descendants. This is useful for visualizing the tree structure in trace
+   * logs.
+   *
+   * @return {String}
+   */
+  toASCIITreeString(prefix = "") {
+    if (!this.isFolder()) {
+      return prefix + "- " + this.toString();
+    }
+    return prefix + "+ " + this.toString() + "\n" + this.children.map(childNode =>
+      childNode.toASCIITreeString(`${prefix}| `)
+    ).join("\n");
+  }
+
+  /**
+   * Returns a representation of the node for logging. This should be compact,
+   * because the merger logs every local and remote node when trace logging is
+   * enabled.
+   *
+   * @return {String}
+   *         A string in the form of "bookmarkAAAA (B; 1.234s; !)", where
+   *         "B" is the kind, "1.234s" is the age, and "!" indicates that the
+   *         node needs to be merged.
+   */
+  toString() {
+    let info = `${this.kindToString()}; ${this.age.toFixed(3)}s`;
+    if (this.needsMerge) {
+      info += "; !";
+    }
+    return `${this.guid} (${info})`;
+  }
+
+  kindToString() {
+    switch (this.kind) {
+      case SyncedBookmarksMirror.KIND.BOOKMARK:
+        return "B";
+      case SyncedBookmarksMirror.KIND.QUERY:
+        return "Q";
+      case SyncedBookmarksMirror.KIND.FOLDER:
+        return "F";
+      case SyncedBookmarksMirror.KIND.LIVEMARK:
+        return "L";
+      case SyncedBookmarksMirror.KIND.SEPARATOR:
+        return "S";
+    }
+    return "?";
+  }
+
+  // Used by `Log.jsm`.
+  toJSON() {
+    return this.toString();
+  }
 }
 
 /**
  * A complete, rooted tree with tombstones.
  */
 class BookmarkTree {
   constructor(root) {
     this.byGuid = new Map();
@@ -2763,19 +2867,26 @@ class BookmarkTree {
       }
       yield guid;
     }
     for (let guid of this.deletedGuids) {
       yield guid;
     }
   }
 
-  toJSON() {
-    let deleted = Array.from(this.deletedGuids);
-    return { root: this.root, deleted };
+  /**
+   * Generates an ASCII art representation of the complete tree. Deleted GUIDs
+   * are prefixed with "~".
+   *
+   * @return {String}
+   */
+  toASCIITreeString() {
+    return this.root.toASCIITreeString() + "\n" + Array.from(this.deletedGuids,
+      guid => `~${guid}`
+    ).join(", ");
   }
 }
 
 /**
  * A node in a merged bookmark tree. Holds the local node, remote node,
  * merged children, and a merge state indicating which side to prefer.
  */
 class MergedBookmarkNode {
@@ -2871,16 +2982,48 @@ class MergedBookmarkNode {
             "Can't take remote value state without remote node");
         }
         return this.remoteNode;
     }
     MirrorLog.error("Merged node ${guid} has unknown value state ${valueState}",
                     { guid: this.guid, valueState });
     throw new TypeError("Can't take unknown value state");
   }
+
+  /**
+   * Generates an ASCII art representation of the merged node and its
+   * descendants. This is similar to the format generated by
+   * `BookmarkNode#toASCIITreeString`, but logs value and structure states for
+   * merged children.
+   *
+   * @return {String}
+   */
+  toASCIITreeString(prefix = "") {
+    if (!this.mergedChildren.length) {
+      return prefix + "- " + this.toString();
+    }
+    return prefix + "+ " + this.toString() + "\n" + this.mergedChildren.map(
+      mergedChildNode => mergedChildNode.toASCIITreeString(`${prefix}| `)
+    ).join("\n");
+  }
+
+  /**
+   * Returns a representation of the merged node for logging.
+   *
+   * @return {String}
+   *         A string in the form of "bookmarkAAAA (V: R, S: R)", where
+   *         "V" is the value state and "R" is the structure state.
+   */
+  toString() {
+    return `${this.guid} ${this.mergeState.toString()}`;
+  }
+
+  toJSON() {
+    return this.toString();
+  }
 }
 
 // Caches bookmark nodes containing the decided value and structure.
 MergedBookmarkNode.cachedBookmarkNodes = new WeakMap();
 
 /**
  * A two-way merger that produces a complete merged tree from a complete local
  * tree and a complete remote tree with changes since the last sync.
@@ -3663,16 +3806,35 @@ class BookmarkMerger {
         continue;
       }
       this.telemetryEvents.push({ value: "dupe" });
       newLocalNode = localChildNode;
       break;
     }
     return newLocalNode;
   }
+
+  /**
+   * Returns an array of local ("L: ~bookmarkAAAA, ~bookmarkBBBB") and remote
+   * ("R: ~bookmarkCCCC, ~bookmarkDDDD") deletions for logging.
+   *
+   * @return {String[]}
+   */
+  deletionsToStrings() {
+    let infos = [];
+    if (this.deleteLocally.size) {
+      infos.push("L: " + Array.from(this.deleteLocally,
+        guid => `~${guid}`).join(", "));
+    }
+    if (this.deleteRemotely.size) {
+      infos.push("R: " + Array.from(this.deleteRemotely,
+        guid => `~${guid}`).join(", "));
+    }
+    return infos;
+  }
 }
 
 /**
  * Determines if two new local and remote nodes are of the same kind, and have
  * similar contents.
  *
  * - Bookmarks must have the same title and URL.
  * - Smart bookmarks must have the same smart bookmark name. Other queries