--- 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);