Bug 1455413 - Use debug logging for bookmarks mirror trees; trace logging for details. r=tcsc
authorKit Cambridge <kit@yakshaving.ninja>
Thu, 19 Apr 2018 12:19:32 -0700
changeset 468142 a24163782fb72468fa3f83aacd9c15278ff060f3
parent 468141 77aa2a89aa37ea92194f79518895febc737ce341
child 468143 f7eaee35dcd2dab819bcadcdb9bba2ed53cc697f
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
bugs1455413
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 1455413 - Use debug logging for bookmarks mirror trees; trace logging for details. r=tcsc MozReview-Commit-ID: IVa4KzdNHrR
toolkit/components/places/SyncedBookmarksMirror.jsm
--- a/toolkit/components/places/SyncedBookmarksMirror.jsm
+++ b/toolkit/components/places/SyncedBookmarksMirror.jsm
@@ -459,33 +459,33 @@ class SyncedBookmarksMirror {
     // mirror, and we're holding the Sync lock at this point.
     MirrorLog.debug("Building remote tree from mirror");
     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" +
+    if (MirrorLog.level <= Log.Level.Debug) {
+      MirrorLog.debug("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 { 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" +
+      if (MirrorLog.level <= Log.Level.Debug) {
+        MirrorLog.debug("Built local tree from Places\n" +
                         localTree.toASCIITreeString());
       }
 
       MirrorLog.debug("Fetching content info for new mirror items");
       let {
         result: newRemoteContents,
         time: remoteContentsTiming,
       } = await withTiming(
@@ -518,18 +518,18 @@ class SyncedBookmarksMirror {
         ));
         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([
+      if (MirrorLog.level <= Log.Level.Debug) {
+        MirrorLog.debug([
           "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
@@ -588,17 +588,17 @@ class SyncedBookmarksMirror {
 
       return changeRecords;
     });
 
     MirrorLog.debug("Replaying recorded observer notifications");
     try {
       await observersToNotify.notifyAll();
     } catch (ex) {
-      MirrorLog.error("Error notifying Places observers", ex);
+      MirrorLog.warn("Error notifying Places observers", ex);
     }
 
     for (let value in applyStats) {
       let extra = normalizeExtraTelemetryFields(applyStats[value]);
       if (extra) {
         this.recordTelemetryEvent("mirror", "apply", value, extra);
       }
     }
@@ -1281,28 +1281,28 @@ class SyncedBookmarksMirror {
    *        The root of the merged bookmark tree.
    * @param {Object[]} localDeletions
    *        `{ guid, level }` tuples for items to remove from Places and flag as
    *        merged.
    * @param {String[]} remoteDeletions
    *        Remotely deleted GUIDs that should be flagged as merged.
    */
   async updateLocalItemsInPlaces(mergedRoot, localDeletions, remoteDeletions) {
-    MirrorLog.debug("Setting up merge states table");
+    MirrorLog.trace("Setting up merge states table");
     let mergeStatesParams = Array.from(mergedRoot.mergeStatesParams());
     if (mergeStatesParams.length) {
       await this.db.execute(`
         INSERT INTO mergeStates(localGuid, mergedGuid, parentGuid, level,
                                 position, valueState, structureState)
         VALUES(IFNULL(:localGuid, :mergedGuid), :mergedGuid, :parentGuid,
                :level, :position, :valueState, :structureState)`,
         mergeStatesParams);
     }
 
-    MirrorLog.debug("Inserting new URLs into Places");
+    MirrorLog.trace("Inserting new URLs into Places");
     await this.db.execute(`
       INSERT OR IGNORE INTO moz_places(url, url_hash, rev_host, hidden,
                                        frecency, guid)
       SELECT u.url, u.hash, u.revHost, 0,
              (CASE v.kind WHEN :queryKind THEN 0 ELSE -1 END),
              IFNULL((SELECT h.guid FROM moz_places h
                      WHERE h.url_hash = u.hash AND
                            h.url = u.url), u.guid)
@@ -1311,29 +1311,29 @@ class SyncedBookmarksMirror {
       JOIN mergeStates r ON r.mergedGuid = v.guid
       WHERE r.valueState = :valueState`,
       { queryKind: SyncedBookmarksMirror.KIND.QUERY,
         valueState: BookmarkMergeState.TYPE.REMOTE });
     await this.db.execute(`DELETE FROM moz_updatehostsinsert_temp`);
 
     // Deleting from `itemsToMerge` fires the `insertNewLocalItems` and
     // `updateExistingLocalItems` triggers.
-    MirrorLog.debug("Updating value states for local bookmarks");
+    MirrorLog.trace("Updating value states for local bookmarks");
     await this.db.execute(`DELETE FROM itemsToMerge`);
 
     // Update the structure. The mirror stores structure info in a separate
     // table, like iOS, while Places stores structure info on children. We don't
     // check the parent's merge state here because our merged tree might
     // diverge from the server if we're missing children, or moved children
     // without parents to "unfiled". In that case, we *don't* want to reupload
     // the new local structure to the server.
-    MirrorLog.debug("Updating structure states for local bookmarks");
+    MirrorLog.trace("Updating structure states for local bookmarks");
     await this.db.execute(`DELETE FROM structureToMerge`);
 
-    MirrorLog.debug("Removing remotely deleted items from Places");
+    MirrorLog.trace("Removing remotely deleted items from Places");
     for (let chunk of PlacesSyncUtils.chunkArray(localDeletions,
       SQLITE_MAX_VARIABLE_NUMBER)) {
 
       let guids = chunk.map(({ guid }) => guid);
 
       // Record item removed notifications.
       await this.db.execute(`
         WITH
@@ -1379,17 +1379,17 @@ class SyncedBookmarksMirror {
       await this.db.execute(`
         UPDATE items SET
           needsMerge = 0
         WHERE needsMerge AND
               guid IN (SELECT guid FROM itemsRemoved
                        WHERE NOT isUntagging)`);
     }
 
-    MirrorLog.debug("Flagging remotely deleted items as merged");
+    MirrorLog.trace("Flagging remotely deleted items as merged");
     for (let chunk of PlacesSyncUtils.chunkArray(remoteDeletions,
       SQLITE_MAX_VARIABLE_NUMBER)) {
 
       await this.db.execute(`
         UPDATE items SET
           needsMerge = 0
         WHERE needsMerge AND
               guid IN (${new Array(chunk.length).fill("?").join(",")})`,
@@ -1399,17 +1399,17 @@ class SyncedBookmarksMirror {
 
   /**
    * Records Places observer notifications for removed, added, moved, and
    * changed items.
    *
    * @param {BookmarkObserverRecorder} observersToNotify
    */
   async noteObserverChanges(observersToNotify) {
-    MirrorLog.debug("Recording observer notifications for removed items");
+    MirrorLog.trace("Recording observer notifications for removed items");
     // `ORDER BY v.level DESC` sorts deleted children before parents, to ensure
     // that we update caches in the correct order (bug 1297941). We also order
     // by parent and position so that the notifications are well-ordered for
     // tests.
     let removedItemRows = await this.db.execute(`
       SELECT v.itemId AS id, v.parentId, v.parentGuid, v.position, v.type,
              h.url, v.guid, v.isUntagging
       FROM itemsRemoved v
@@ -1424,17 +1424,17 @@ class SyncedBookmarksMirror {
         urlHref: row.getResultByName("url"),
         guid: row.getResultByName("guid"),
         parentGuid: row.getResultByName("parentGuid"),
         isUntagging: row.getResultByName("isUntagging"),
       };
       observersToNotify.noteItemRemoved(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for changed GUIDs");
+    MirrorLog.trace("Recording observer notifications for changed GUIDs");
     let changedGuidRows = await this.db.execute(`
       SELECT b.id, b.lastModified, b.type, b.guid AS newGuid,
              c.oldGuid, p.id AS parentId, p.guid AS parentGuid
       FROM guidsChanged c
       JOIN moz_bookmarks b ON b.id = c.itemId
       JOIN moz_bookmarks p ON p.id = b.parent
       ORDER BY c.level, p.id, b.position`);
     for await (let row of yieldingIterator(changedGuidRows)) {
@@ -1445,17 +1445,17 @@ class SyncedBookmarksMirror {
         newGuid: row.getResultByName("newGuid"),
         oldGuid: row.getResultByName("oldGuid"),
         parentId: row.getResultByName("parentId"),
         parentGuid: row.getResultByName("parentGuid"),
       };
       observersToNotify.noteGuidChanged(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for new items");
+    MirrorLog.trace("Recording observer notifications for new items");
     let newItemRows = await this.db.execute(`
       SELECT b.id, p.id AS parentId, b.position, b.type, h.url,
              IFNULL(b.title, "") AS title, b.dateAdded, b.guid,
              p.guid AS parentGuid, n.isTagging
       FROM itemsAdded n
       JOIN moz_bookmarks b ON b.guid = n.guid
       JOIN moz_bookmarks p ON p.id = b.parent
       LEFT JOIN moz_places h ON h.id = b.fk
@@ -1471,17 +1471,17 @@ class SyncedBookmarksMirror {
         dateAdded: row.getResultByName("dateAdded"),
         guid: row.getResultByName("guid"),
         parentGuid: row.getResultByName("parentGuid"),
         isTagging: row.getResultByName("isTagging"),
       };
       observersToNotify.noteItemAdded(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for moved items");
+    MirrorLog.trace("Recording observer notifications for moved items");
     let movedItemRows = await this.db.execute(`
       SELECT b.id, b.guid, b.type, p.id AS newParentId, c.oldParentId,
              p.guid AS newParentGuid, c.oldParentGuid,
              b.position AS newPosition, c.oldPosition
       FROM itemsMoved c
       JOIN moz_bookmarks b ON b.id = c.itemId
       JOIN moz_bookmarks p ON p.id = b.parent
       ORDER BY c.level, newParentId, newPosition`);
@@ -1495,17 +1495,17 @@ class SyncedBookmarksMirror {
         newParentGuid: row.getResultByName("newParentGuid"),
         oldParentGuid: row.getResultByName("oldParentGuid"),
         newPosition: row.getResultByName("newPosition"),
         oldPosition: row.getResultByName("oldPosition"),
       };
       observersToNotify.noteItemMoved(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for changed items");
+    MirrorLog.trace("Recording observer notifications for changed items");
     let changedItemRows = await this.db.execute(`
       SELECT b.id, b.guid, b.lastModified, b.type,
              IFNULL(b.title, "") AS newTitle,
              IFNULL(c.oldTitle, "") AS oldTitle,
              h.url AS newURL, i.url AS oldURL,
              p.id AS parentId, p.guid AS parentGuid
       FROM itemsChanged c
       JOIN moz_bookmarks b ON b.id = c.itemId
@@ -1524,31 +1524,31 @@ class SyncedBookmarksMirror {
         newURLHref: row.getResultByName("newURL"),
         oldURLHref: row.getResultByName("oldURL"),
         parentId: row.getResultByName("parentId"),
         parentGuid: row.getResultByName("parentGuid"),
       };
       observersToNotify.noteItemChanged(info);
     }
 
-    MirrorLog.debug("Recording observer notifications for changed annos");
+    MirrorLog.trace("Recording observer notifications for changed annos");
     let annoRows = await this.db.execute(`
       SELECT itemId, annoName, wasRemoved FROM annosChanged
       ORDER BY itemId`);
     for await (let row of yieldingIterator(annoRows)) {
       let id = row.getResultByName("itemId");
       let name = row.getResultByName("annoName");
       if (row.getResultByName("wasRemoved")) {
         observersToNotify.noteAnnoRemoved(id, name);
       } else {
         observersToNotify.noteAnnoSet(id, name);
       }
     }
 
-    MirrorLog.debug("Recording notifications for changed keywords");
+    MirrorLog.trace("Recording notifications for changed keywords");
     let keywordsChangedRows = await this.db.execute(`
       SELECT EXISTS(SELECT 1 FROM itemsAdded WHERE keywordChanged) OR
              EXISTS(SELECT 1 FROM itemsChanged WHERE keywordChanged)
              AS keywordsChanged`);
     observersToNotify.shouldInvalidateKeywords =
       !!keywordsChangedRows[0].getResultByName("keywordsChanged");
   }
 
@@ -2794,17 +2794,17 @@ async function inflateTree(tree, pseudoT
 
 // 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`);
+  MirrorLog.trace(`${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.
  */
@@ -4577,17 +4577,17 @@ class BookmarkObserverRecorder {
     await this.notifyAnnoObservers();
     if (this.shouldInvalidateLivemarks) {
       await PlacesUtils.livemarks.invalidateCachedLivemarks();
     }
     await this.updateFrecencies();
   }
 
   async updateFrecencies() {
-    MirrorLog.debug("Recalculating frecencies for new URLs");
+    MirrorLog.trace("Recalculating frecencies for new URLs");
     await this.db.execute(`
       UPDATE moz_places SET
         frecency = CALCULATE_FRECENCY(id)
       WHERE frecency = -1`);
   }
 
   noteItemAdded(info) {
     let uri = info.urlHref ? Services.io.newURI(info.urlHref) : null;
@@ -4670,32 +4670,32 @@ class BookmarkObserverRecorder {
     }
     this.annoObserverNotifications.push({
       name: "onItemAnnotationRemoved",
       args: [id, name, PlacesUtils.bookmarks.SOURCES.SYNC],
     });
   }
 
   async notifyBookmarkObservers() {
-    MirrorLog.debug("Notifying bookmark observers");
+    MirrorLog.trace("Notifying bookmark observers");
     let observers = PlacesUtils.bookmarks.getObservers();
     for (let observer of observers) {
       this.notifyObserver(observer, "onBeginUpdateBatch");
       for await (let info of yieldingIterator(this.bookmarkObserverNotifications)) {
         if (info.isTagging && observer.skipTags) {
           continue;
         }
         this.notifyObserver(observer, info.name, info.args);
       }
       this.notifyObserver(observer, "onEndUpdateBatch");
     }
   }
 
   async notifyAnnoObservers() {
-    MirrorLog.debug("Notifying anno observers");
+    MirrorLog.trace("Notifying anno observers");
     let observers = PlacesUtils.annotations.getObservers();
     for (let observer of observers) {
       let wrapped = yieldingIterator(this.annoObserverNotifications);
       for await (let { name, args } of wrapped) {
         this.notifyObserver(observer, name, args);
       }
     }
   }