mozilla
/
gecko-dev
зеркало из https://github.com/mozilla/gecko-dev.git
1
0
Форкнуть 0
Код Задачи Пакеты Проекты Релизы Вики Активность

Bug 1461009 - Rework bookmarks mirror event telemetry. r=tcsc 

MozReview-Commit-ID: L5pXbAaclDe

--HG--
extra : rebase_source : 32f47d4dfe37c042b2a4cdfe8cda8b2e3a975319
This commit is contained in:
Kit Cambridge 2018-05-10 18:25:20 -07:00
Родитель 64d055dbea
Коммит 6df0100b49
5 изменённых файлов: 199 добавлений и 217 удалений
Показать статистику Скачать Patch файл Скачать Diff файл Показать все файлы Свернуть все файлы

264
toolkit/components/places/SyncedBookmarksMirror.jsm
Просмотреть файл

@ -60,7 +60,6 @@ XPCOMUtils.defineLazyModuleGetters(this, {
Async: "resource://services-common/async.js",
AsyncShutdown: "resource://gre/modules/AsyncShutdown.jsm",
Log: "resource://gre/modules/Log.jsm",
ObjectUtils: "resource://gre/modules/ObjectUtils.jsm",
OS: "resource://gre/modules/osfile.jsm",
PlacesSyncUtils: "resource://gre/modules/PlacesSyncUtils.jsm",
PlacesUtils: "resource://gre/modules/PlacesUtils.jsm",
@ -224,8 +223,7 @@ class SyncedBookmarksMirror {
try {
let info = await OS.File.stat(path);
let size = Math.floor(info.size / 1024);
options.recordTelemetryEvent("mirror", "open", "success",
normalizeExtraTelemetryFields({ size }));
options.recordTelemetryEvent("mirror", "open", "success", { size });
} catch (ex) {
MirrorLog.warn("Error recording stats for mirror database size", ex);
}
@ -415,26 +413,32 @@ class SyncedBookmarksMirror {
async apply({ localTimeSeconds = Date.now() / 1000,
remoteTimeSeconds = 0,
weakUpload = [] } = {}) {
// We intentionally don't use `executeBeforeShutdown` in this function,
// 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 hasChanges = weakUpload.length > 0 || (await this.hasChanges());
if (!hasChanges) {
MirrorLog.debug("No changes detected in both mirror and Places");
return {};
}
// We intentionally don't use `executeBeforeShutdown` in this function,
// 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();
// The flow ID is used to correlate telemetry events for each sync.
let flowID = PlacesUtils.history.makeGuid();
let { missingParents, missingChildren, parentsWithGaps } =
await this.fetchRemoteOrphans();
if (missingParents.length) {
MirrorLog.warn("Temporarily reparenting remote items with missing " +
"parents to unfiled", missingParents);
this.recordTelemetryEvent("mirror", "orphans", "parents",
normalizeExtraTelemetryFields({ count: missingParents.length }));
}
if (missingChildren.length) {
MirrorLog.warn("Remote tree missing items", missingChildren);
this.recordTelemetryEvent("mirror", "orphans", "children",
normalizeExtraTelemetryFields({ count: missingChildren.length }));
}
if (parentsWithGaps.length) {
MirrorLog.warn("Remote tree has parents with gaps in positions",
parentsWithGaps);
}
let { missingLocal, missingRemote, wrongSyncStatus } =
@ -442,34 +446,36 @@ class SyncedBookmarksMirror {
if (missingLocal.length) {
MirrorLog.warn("Remote tree has merged items that don't exist locally",
missingLocal);
this.recordTelemetryEvent("mirror", "inconsistencies", "local",
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",
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",
normalizeExtraTelemetryFields({ count: wrongSyncStatus.length }));
}
let applyStats = {};
this.recordTelemetryEvent("mirror", "apply", "problems", {
flowID,
missingParents: missingParents.length,
missingChildren: missingChildren.length,
parentsWithGaps: parentsWithGaps.length,
missingLocal: missingLocal.length,
missingRemote: missingRemote.length,
wrongSyncStatus: wrongSyncStatus.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 { result: remoteTree, time: remoteTreeTiming } = await withTiming(
"Fetch remote tree",
() => this.fetchRemoteTree(remoteTimeSeconds)
let remoteTree = await withTiming(
"Building remote tree from mirror",
() => this.fetchRemoteTree(remoteTimeSeconds),
(time, tree) => this.recordTelemetryEvent("mirror", "apply",
"fetchRemoteTree", { flowID, time, deletions: tree.deletedGuids.size,
nodes: tree.byGuid.size })
);
applyStats.remoteTree = { time: remoteTreeTiming,
count: remoteTree.guidCount };
if (MirrorLog.level <= Log.Level.Debug) {
MirrorLog.debug("Built remote tree from mirror\n" +
remoteTree.toASCIITreeString());
@ -477,57 +483,51 @@ class SyncedBookmarksMirror {
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)
let changeRecords;
try {
changeRecords = await this.db.executeTransaction(async () => {
let localTree = await withTiming(
"Building local tree from Places",
() => this.fetchLocalTree(localTimeSeconds),
(time, tree) => this.recordTelemetryEvent("mirror", "apply",
"fetchLocalTree", { flowID, time, deletions: tree.deletedGuids.size,
nodes: tree.byGuid.size })
);
applyStats.localTree = { time: localTreeTiming,
count: localTree.guidCount };
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(
"Fetch new remote contents",
() => this.fetchNewRemoteContents()
let newRemoteContents = await withTiming(
"Fetching content info for new mirror items",
() => this.fetchNewRemoteContents(),
(time, contents) => this.recordTelemetryEvent("mirror", "apply",
"fetchNewRemoteContents", { flowID, time, count: contents.size })
);
applyStats.remoteContents = { time: remoteContentsTiming,
count: newRemoteContents.size };
MirrorLog.debug("Fetching content info for new Places items");
let {
result: newLocalContents,
time: localContentsTiming,
} = await withTiming(
"Fetch new local contents",
() => this.fetchNewLocalContents()
let newLocalContents = await withTiming(
"Fetching content info for new Places items",
() => this.fetchNewLocalContents(),
(time, contents) => this.recordTelemetryEvent("mirror", "apply",
"fetchNewLocalContents", { flowID, time, count: contents.size })
);
applyStats.localContents = { time: localContentsTiming,
count: newLocalContents.size };
MirrorLog.debug("Building complete merged tree");
let merger = new BookmarkMerger(localTree, newLocalContents,
remoteTree, newRemoteContents);
let mergedRoot;
try {
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);
}
let mergedRoot = await withTiming(
"Building complete merged tree",
() => merger.merge(),
time => {
this.recordTelemetryEvent("mirror", "apply", "merge",
{ flowID, time, nodes: merger.mergedGuids.size,
localDeletions: merger.deleteLocally.size,
remoteDeletions: merger.deleteRemotely.size,
dupes: merger.dupeCount });
this.recordTelemetryEvent("mirror", "merge", "structure",
merger.structureCounts);
}
);
if (MirrorLog.level <= Log.Level.Debug) {
MirrorLog.debug([
@ -549,16 +549,18 @@ class SyncedBookmarksMirror {
"Merged tree doesn't mention all items from remote tree");
}
MirrorLog.debug("Applying merged tree");
await withTiming(
"Applying merged tree",
async () => {
let deletions = [];
for await (let deletion of yieldingIterator(merger.deletions())) {
deletions.push(deletion);
}
let { time: updateTiming } = await withTiming(
"Apply merged tree",
() => this.updateLocalItemsInPlaces(mergedRoot, deletions)
await this.updateLocalItemsInPlaces(mergedRoot, deletions);
},
time => this.recordTelemetryEvent("mirror", "apply",
"updateLocalItemsInPlaces", { flowID, time })
);
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
@ -566,21 +568,31 @@ class SyncedBookmarksMirror {
// incomplete structure might cause us to miss or record wrong parents and
// positions.
MirrorLog.debug("Recording observer notifications");
await this.noteObserverChanges(observersToNotify);
await withTiming(
"Recording observer notifications",
() => this.noteObserverChanges(observersToNotify),
time => this.recordTelemetryEvent("mirror", "apply",
"noteObserverChanges", { flowID, time })
);
let {
result: changeRecords,
time: stageTiming,
} = await withTiming("Stage outgoing items", async () => {
MirrorLog.debug("Staging locally changed items for upload");
await this.stageItemsToUpload(weakUpload);
await withTiming(
"Staging locally changed items for upload",
() => this.stageItemsToUpload(weakUpload),
time => this.recordTelemetryEvent("mirror", "apply",
"stageItemsToUpload", { flowID, time })
);
MirrorLog.debug("Fetching records for local items to upload");
return this.fetchLocalChangeRecords();
});
applyStats.stage = { time: stageTiming };
let changeRecords = await withTiming(
"Fetching records for local items to upload",
() => this.fetchLocalChangeRecords(),
(time, records) => this.recordTelemetryEvent("mirror", "apply",
"fetchLocalChangeRecords", { flowID,
count: Object.keys(records).length })
);
await withTiming(
"Cleaning up merge tables",
async () => {
await this.db.execute(`DELETE FROM mergeStates`);
await this.db.execute(`DELETE FROM itemsAdded`);
await this.db.execute(`DELETE FROM guidsChanged`);
@ -590,9 +602,21 @@ class SyncedBookmarksMirror {
await this.db.execute(`DELETE FROM annosChanged`);
await this.db.execute(`DELETE FROM idsToWeaklyUpload`);
await this.db.execute(`DELETE FROM itemsToUpload`);
},
time => this.recordTelemetryEvent("mirror", "apply", "cleanup",
{ flowID, time })
);
return changeRecords;
});
} catch (ex) {
// Include the error message in the event payload, since we can't
// easily correlate event telemetry to engine errors in the Sync ping.
let why = (typeof ex.message == "string" ? ex.message :
String(ex)).slice(0, 85);
this.recordTelemetryEvent("mirror", "apply", "error", { flowID, why });
throw ex;
}
MirrorLog.debug("Replaying recorded observer notifications");
try {
@ -601,13 +625,6 @@ class SyncedBookmarksMirror {
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);
}
}
return changeRecords;
}
@ -1867,28 +1884,6 @@ class DatabaseCorruptError extends Error {
}
}
// 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) {
@ -2807,15 +2802,31 @@ async function inflateTree(tree, pseudoTree, parentNode) {
}
}
// 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) {
/**
* Measures and logs the time taken to execute a function, using a monotonic
* clock.
*
* @param {String} name
* The name of the operation, used for logging.
* @param {Function} func
* The function to time.
* @param {Function} recordTiming
* A function with the signature `(time: Number, result: Object?)`,
* where `time` is the measured time, and `result` is the return
* value of the timed function.
* @return The return value of the timed function.
*/
async function withTiming(name, func, recordTiming) {
MirrorLog.debug(name);
let startTime = Cu.now();
let result = await func();
let elapsedTime = Cu.now() - startTime;
MirrorLog.trace(`${name} took ${elapsedTime.toFixed(3)}ms`);
return { result, time: elapsedTime };
recordTiming(elapsedTime, result);
return result;
}
/**
@ -3166,10 +3177,6 @@ class BookmarkTree {
this.deletedGuids = new Set();
}
get guidCount() {
return this.byGuid.size + this.deletedGuids.size;
}
isDeleted(guid) {
return this.deletedGuids.has(guid);
}
@ -3354,22 +3361,6 @@ class BookmarkMerger {
remoteDeletes: 0, // Remote folder deletion wins over local change.
};
this.dupeCount = 0;
this.extraTelemetryEvents = [];
}
summarizeTelemetryEvents() {
let events = [...this.extraTelemetryEvents];
if (this.dupeCount > 0) {
events.push({
value: "dupes",
extra: normalizeExtraTelemetryFields({ count: this.dupeCount }),
});
}
let structureExtra = normalizeExtraTelemetryFields(this.structureCounts);
if (structureExtra) {
events.push({ value: "structure", extra: structureExtra });
}
return events;
}
async merge() {
@ -3520,11 +3511,6 @@ class BookmarkMerger {
if (!localNode.hasCompatibleKind(remoteNode)) {
MirrorLog.error("Merging local ${localNode} and remote ${remoteNode} " +
"with different kinds", { localNode, remoteNode });
this.extraTelemetryEvents.push({
value: "kind-mismatch",
extra: { local: localNode.kindToString().toLowerCase(),
remote: remoteNode.kindToString().toLowerCase() },
});
throw new SyncedBookmarksMirror.ConsistencyError(
"Can't merge different item kinds");
}

6
toolkit/components/places/tests/sync/test_bookmark_deduping.js
Просмотреть файл

@ -86,11 +86,9 @@ add_task(async function test_duping_local_newer() {
});
deepEqual(await buf.fetchUnmergedGuids(), [], "Should merge all items");
deepEqual(mergeTelemetryEvents, [{
value: "dupes",
extra: { count: "2" },
}, {
value: "structure",
extra: { new: "1" },
extra: { new: 1, remoteRevives: 0, localDeletes: 0, localRevives: 0,
remoteDeletes: 0 },
}], "Should record telemetry with dupe counts");
let menuInfo = await PlacesUtils.bookmarks.fetch(

9
toolkit/components/places/tests/sync/test_bookmark_deletion.js
Просмотреть файл

@ -114,7 +114,8 @@ add_task(async function test_complex_orphaning() {
deepEqual(await buf.fetchUnmergedGuids(), [], "Should merge all items");
deepEqual(mergeTelemetryEvents, [{
value: "structure",
extra: { new: "2", localDeletes: "1", remoteDeletes: "1" },
extra: { new: 2, remoteRevives: 0, localDeletes: 1, localRevives: 0,
remoteDeletes: 1 },
}], "Should record telemetry with structure change counts");
let idsToUpload = inspectChangeRecords(changesToUpload);
@ -306,7 +307,8 @@ add_task(async function test_locally_modified_remotely_deleted() {
deepEqual(await buf.fetchUnmergedGuids(), [], "Should merge all items");
deepEqual(mergeTelemetryEvents, [{
value: "structure",
extra: { new: "1", localRevives: "1", remoteDeletes: "2" },
extra: { new: 1, remoteRevives: 0, localDeletes: 0, localRevives: 1,
remoteDeletes: 2 },
}], "Should record telemetry for local item and remote folder deletions");
let idsToUpload = inspectChangeRecords(changesToUpload);
@ -453,7 +455,8 @@ add_task(async function test_locally_deleted_remotely_modified() {
deepEqual(await buf.fetchUnmergedGuids(), [], "Should merge all items");
deepEqual(mergeTelemetryEvents, [{
value: "structure",
extra: { new: "1", remoteRevives: "1", localDeletes: "2" },
extra: { new: 1, remoteRevives: 1, localDeletes: 2, localRevives: 0,
remoteDeletes: 0 },
}], "Should record telemetry for remote item and local folder deletions");
let idsToUpload = inspectChangeRecords(changesToUpload);

30
toolkit/components/places/tests/sync/test_bookmark_kinds.js
Просмотреть файл

@ -418,15 +418,12 @@ add_task(async function test_mismatched_but_compatible_folder_types() {
});
add_task(async function test_mismatched_but_incompatible_folder_types() {
let sawMismatchEvent = false;
let sawMismatchError = false;
let recordTelemetryEvent = (object, method, value, extra) => {
// expecting to see a kind-mismatch event.
if (value == "kind-mismatch" &&
extra.local && typeof extra.local == "string" &&
extra.local == "livemark" &&
extra.remote && typeof extra.remote == "string" &&
extra.remote == "folder") {
sawMismatchEvent = true;
// expecting to see an error for kind mismatches.
if (method == "apply" && value == "error" &&
extra && extra.why == "Can't merge different item kinds") {
sawMismatchError = true;
}
};
let buf = await openMirror("mismatched_incompatible_types",
@ -458,7 +455,7 @@ add_task(async function test_mismatched_but_incompatible_folder_types() {
info("Apply remote, should fail");
await Assert.rejects(buf.apply(), /Can't merge different item kinds/);
Assert.ok(sawMismatchEvent, "saw the correct mismatch event");
Assert.ok(sawMismatchError, "saw the correct mismatch event");
} finally {
await buf.finalize();
await PlacesUtils.bookmarks.eraseEverything();
@ -539,15 +536,12 @@ add_task(async function test_different_but_compatible_bookmark_types() {
});
add_task(async function test_incompatible_types() {
let sawMismatchEvent = false;
let sawMismatchError = false;
let recordTelemetryEvent = (object, method, value, extra) => {
// expecting to see a kind-mismatch event.
if (value == "kind-mismatch" &&
extra.local && typeof extra.local == "string" &&
extra.local == "bookmark" &&
extra.remote && typeof extra.remote == "string" &&
extra.remote == "folder") {
sawMismatchEvent = true;
// expecting to see an error for kind mismatches.
if (method == "apply" && value == "error" &&
extra && extra.why == "Can't merge different item kinds") {
sawMismatchError = true;
}
};
try {
@ -582,7 +576,7 @@ add_task(async function test_incompatible_types() {
await PlacesTestUtils.markBookmarksAsSynced();
await Assert.rejects(buf.apply(), /Can't merge different item kinds/);
Assert.ok(sawMismatchEvent, "saw expected mismatch event");
Assert.ok(sawMismatchError, "saw expected mismatch event");
} finally {
await PlacesUtils.bookmarks.eraseEverything();
await PlacesSyncUtils.bookmarks.reset();

3
toolkit/components/places/tests/sync/test_bookmark_structure_changes.js
Просмотреть файл

@ -647,7 +647,8 @@ add_task(async function test_complex_move_with_additions() {
deepEqual(await buf.fetchUnmergedGuids(), [], "Should merge all items");
deepEqual(mergeTelemetryEvents, [{
value: "structure",
extra: { new: "1" },
extra: { new: 1, remoteRevives: 0, localDeletes: 0, localRevives: 0,
remoteDeletes: 0 },
}], "Should record telemetry with structure change counts");
let idsToUpload = inspectChangeRecords(changesToUpload);