Bug 853388: Add telemetry measurements; r=Unfocused,vladan

This commit is contained in:
Irving Reid 2013-08-22 11:56:28 -04:00
parent dade0c8d34
commit 6df6254843
5 changed files with 136 additions and 59 deletions

View File

@ -2131,6 +2131,15 @@ this.AddonManagerPrivate = {
getSimpleMeasures: function AMP_getSimpleMeasures() {
return this._simpleMeasures;
},
// Start a timer, record a simple measure of the time interval when
// timer.done() is called
simpleTimer: function(aName) {
let startTime = Date.now();
return {
done: () => AddonManagerPrivate.recordSimpleMeasure(aName, Date.now() - startTime)
};
}
};

View File

@ -94,11 +94,8 @@ const KEY_APP_SYSTEM_LOCAL = "app-system-local";
const KEY_APP_SYSTEM_SHARE = "app-system-share";
const KEY_APP_SYSTEM_USER = "app-system-user";
const UNKNOWN_XPCOM_ABI = "unknownABI";
const XPI_PERMISSION = "install";
const PREFIX_ITEM_URI = "urn:mozilla:item:";
const RDFURI_ITEM_ROOT = "urn:mozilla:item:root"
const RDFURI_INSTALL_MANIFEST_ROOT = "urn:mozilla:install-manifest";
const PREFIX_NS_EM = "http://www.mozilla.org/2004/em-rdf#";
@ -159,6 +156,14 @@ const TYPES = {
dictionary: 64
};
// Keep track of where we are in startup for telemetry
// event happened during XPIDatabase.startup()
const XPI_STARTING = "XPIStarting";
// event happened after startup() but before the final-ui-startup event
const XPI_BEFORE_UI_STARTUP = "BeforeFinalUIStartup";
// event happened after final-ui-startup
const XPI_AFTER_UI_STARTUP = "AfterFinalUIStartup";
const COMPATIBLE_BY_DEFAULT_TYPES = {
extension: true,
dictionary: true
@ -1538,6 +1543,8 @@ var XPIProvider = {
inactiveAddonIDs: [],
// Count of unpacked add-ons
unpackedAddons: 0,
// Keep track of startup phases for telemetry
runPhase: XPI_STARTING,
/**
* Adds or updates a URI mapping for an Addon.id.
@ -1674,6 +1681,7 @@ var XPIProvider = {
*/
startup: function XPI_startup(aAppChanged, aOldAppVersion, aOldPlatformVersion) {
LOG("startup");
this.runPhase = XPI_STARTING;
this.installs = [];
this.installLocations = [];
this.installLocationsByName = {};
@ -1848,9 +1856,19 @@ var XPIProvider = {
}
}, "quit-application-granted", false);
// Detect final-ui-startup for telemetry reporting
Services.obs.addObserver({
observe: function uiStartupObserver(aSubject, aTopic, aData) {
AddonManagerPrivate.recordTimestamp("XPI_finalUIStartup");
XPIProvider.runPhase = XPI_AFTER_UI_STARTUP;
Services.obs.removeObserver(this, "final-ui-startup");
}
}, "final-ui-startup", false);
AddonManagerPrivate.recordTimestamp("XPI_startup_end");
this.extensionsActive = true;
this.runPhase = XPI_BEFORE_UI_STARTUP;
},
/**
@ -1935,7 +1953,7 @@ var XPIProvider = {
var variant = Cc["@mozilla.org/variant;1"].
createInstance(Ci.nsIWritableVariant);
variant.setFromVariant(this.inactiveAddonIDs);
// This *must* be modal as it has to block startup.
var features = "chrome,centerscreen,dialog,titlebar,modal";
var ww = Cc["@mozilla.org/embedcomp/window-watcher;1"].
@ -1979,7 +1997,7 @@ var XPIProvider = {
Services.appinfo.annotateCrashReport("Add-ons", data);
}
catch (e) { }
const TelemetryPing = Cc["@mozilla.org/base/telemetry-ping;1"].getService(Ci.nsITelemetryPing);
TelemetryPing.setAddOns(data);
},
@ -3143,9 +3161,12 @@ var XPIProvider = {
if (aAppChanged !== false)
this.importPermissions();
// If the application version has changed then the database information
// needs to be updated
let updateDatabase = aAppChanged;
// Keep track of whether and why we need to open and update the database at
// startup time.
let updateReasons = [];
if (aAppChanged) {
updateReasons.push("appChanged");
}
// Load the list of bootstrapped add-ons first so processFileChanges can
// modify it
@ -3160,7 +3181,10 @@ var XPIProvider = {
// changes then we must update the database with the information in the
// install locations
let manifests = {};
updateDatabase = this.processPendingFileChanges(manifests) || updateDatabase;
let updated = this.processPendingFileChanges(manifests);
if (updated) {
updateReasons.push("pendingFileChanges");
}
// This will be true if the previous session made changes that affect the
// active state of add-ons but didn't commit them properly (normally due
@ -3168,33 +3192,41 @@ var XPIProvider = {
let hasPendingChanges = Prefs.getBoolPref(PREF_PENDING_OPERATIONS);
// If the schema appears to have changed then we should update the database
updateDatabase = updateDatabase || DB_SCHEMA != Prefs.getIntPref(PREF_DB_SCHEMA, 0);
if (DB_SCHEMA != Prefs.getIntPref(PREF_DB_SCHEMA, 0)) {
updateReasons.push("schemaChanged");
}
// If the application has changed then check for new distribution add-ons
if (aAppChanged !== false &&
Prefs.getBoolPref(PREF_INSTALL_DISTRO_ADDONS, true))
updateDatabase = this.installDistributionAddons(manifests) || updateDatabase;
{
updated = this.installDistributionAddons(manifests);
if (updated) {
updateReasons.push("installDistributionAddons");
}
}
// Telemetry probe added around getInstallLocationStates() to check perf
let telemetryCaptureTime = new Date();
let telemetryCaptureTime = Date.now();
let state = this.getInstallLocationStates();
let telemetry = Services.telemetry;
telemetry.getHistogramById("CHECK_ADDONS_MODIFIED_MS").add(new Date() - telemetryCaptureTime);
telemetry.getHistogramById("CHECK_ADDONS_MODIFIED_MS").add(Date.now() - telemetryCaptureTime);
if (!updateDatabase) {
// If the state has changed then we must update the database
let cache = Prefs.getCharPref(PREF_INSTALL_CACHE, null);
updateDatabase = cache != JSON.stringify(state);
// If the install directory state has changed then we must update the database
let cache = Prefs.getCharPref(PREF_INSTALL_CACHE, null);
if (cache != JSON.stringify(state)) {
updateReasons.push("directoryState");
}
// If the database doesn't exist and there are add-ons installed then we
// must update the database however if there are no add-ons then there is
// no need to update the database.
let dbFile = FileUtils.getFile(KEY_PROFILEDIR, [FILE_DATABASE], true);
if (!dbFile.exists())
updateDatabase = state.length > 0;
if (!dbFile.exists() && state.length > 0) {
updateReasons.push("needNewDatabase");
}
if (!updateDatabase) {
if (updateReasons.length == 0) {
let bootstrapDescriptors = [this.bootstrappedAddons[b].descriptor
for (b in this.bootstrappedAddons)];
@ -3208,7 +3240,7 @@ var XPIProvider = {
if (bootstrapDescriptors.length > 0) {
WARN("Bootstrap state is invalid (missing add-ons: " + bootstrapDescriptors.toSource() + ")");
updateDatabase = true;
updateReasons.push("missingBootstrapAddon");
}
}
@ -3217,7 +3249,11 @@ var XPIProvider = {
let extensionListChanged = false;
// If the database needs to be updated then open it and then update it
// from the filesystem
if (updateDatabase || hasPendingChanges) {
if (hasPendingChanges) {
updateReasons.push("hasPendingChanges");
}
if (updateReasons.length > 0) {
AddonManagerPrivate.recordSimpleMeasure("XPIDB_startup_load_reasons", updateReasons);
XPIDatabase.syncLoadDB(false);
try {
extensionListChanged = this.processFileChanges(state, manifests,

View File

@ -68,24 +68,6 @@ const DB_BOOL_METADATA = ["visible", "active", "userDisabled", "appDisabled",
"softDisabled", "isForeignInstall",
"hasBinaryComponents", "strictCompatibility"];
const FIELDS_ADDON = "internal_id, id, syncGUID, location, version, type, " +
"internalName, updateURL, updateKey, optionsURL, " +
"optionsType, aboutURL, iconURL, icon64URL, " +
"defaultLocale, visible, active, userDisabled, " +
"appDisabled, pendingUninstall, descriptor, " +
"installDate, updateDate, applyBackgroundUpdates, bootstrap, " +
"skinnable, size, sourceURI, releaseNotesURI, softDisabled, " +
"isForeignInstall, hasBinaryComponents, strictCompatibility";
// Properties that exist in the install manifest
const PROP_METADATA = ["id", "version", "type", "internalName", "updateURL",
"updateKey", "optionsURL", "optionsType", "aboutURL",
"iconURL", "icon64URL"];
const PROP_LOCALE_SINGLE = ["name", "description", "creator", "homepageURL"];
const PROP_LOCALE_MULTI = ["developers", "translators", "contributors"];
const PROP_TARGETAPP = ["id", "minVersion", "maxVersion"];
// Properties to save in JSON file
const PROP_JSON_FIELDS = ["id", "syncGUID", "location", "version", "type",
"internalName", "updateURL", "updateKey", "optionsURL",
@ -549,11 +531,11 @@ this.XPIDatabase = {
* (if false, caller is XPIProvider.checkForChanges() which will rebuild)
*/
syncLoadDB: function XPIDB_syncLoadDB(aRebuildOnError) {
// XXX TELEMETRY report synchronous opens (startup time) vs. delayed opens
this.migrateData = null;
let fstream = null;
let data = "";
try {
let readTimer = AddonManagerPrivate.simpleTimer("XPIDB_syncRead_MS");
LOG("Opening XPI database " + this.jsonFile.path);
fstream = Components.classes["@mozilla.org/network/file-input-stream;1"].
createInstance(Components.interfaces.nsIFileInputStream);
@ -570,11 +552,14 @@ this.XPIDatabase = {
data += str.value;
} while (read != 0);
}
readTimer.done();
this.parseDB(data, aRebuildOnError);
}
catch(e) {
ERROR("Failed to load XPI JSON data from profile", e);
let rebuildTimer = AddonManagerPrivate.simpleTimer("XPIDB_rebuildReadFailed_MS");
this.rebuildDatabase(aRebuildOnError);
rebuildTimer.done();
}
finally {
if (cstream)
@ -582,7 +567,7 @@ this.XPIDatabase = {
}
}
catch (e) {
if (e.result == Cr.NS_ERROR_FILE_NOT_FOUND) {
if (e.result === Cr.NS_ERROR_FILE_NOT_FOUND) {
this.upgradeDB(aRebuildOnError);
}
else {
@ -595,8 +580,10 @@ this.XPIDatabase = {
}
// If an async load was also in progress, resolve that promise with our DB;
// otherwise create a resolved promise
if (this._dbPromise)
if (this._dbPromise) {
AddonManagerPrivate.recordSimpleMeasure("XPIDB_overlapped_load", 1);
this._dbPromise.resolve(this.addonDB);
}
else
this._dbPromise = Promise.resolve(this.addonDB);
},
@ -607,20 +594,27 @@ this.XPIDatabase = {
* If true, synchronously reconstruct the database from installed add-ons
*/
parseDB: function(aData, aRebuildOnError) {
let parseTimer = AddonManagerPrivate.simpleTimer("XPIDB_parseDB_MS");
try {
// dump("Loaded JSON:\n" + aData + "\n");
let inputAddons = JSON.parse(aData);
// Now do some sanity checks on our JSON db
if (!("schemaVersion" in inputAddons) || !("addons" in inputAddons)) {
parseTimer.done();
// Content of JSON file is bad, need to rebuild from scratch
ERROR("bad JSON file contents");
AddonManagerPrivate.recordSimpleMeasure("XPIDB_startupError", "badJSON");
let rebuildTimer = AddonManagerPrivate.simpleTimer("XPIDB_rebuildBadJSON_MS");
this.rebuildDatabase(aRebuildOnError);
rebuildTimer.done();
return;
}
if (inputAddons.schemaVersion != DB_SCHEMA) {
// Handle mismatched JSON schema version. For now, we assume
// compatibility for JSON data, though we throw away any fields we
// don't know about
// don't know about (bug 902956)
AddonManagerPrivate.recordSimpleMeasure("XPIDB_startupError",
"schemaMismatch-" + inputAddons.schemaVersion);
LOG("JSON schema mismatch: expected " + DB_SCHEMA +
", actual " + inputAddons.schemaVersion);
}
@ -631,6 +625,7 @@ this.XPIDatabase = {
let newAddon = new DBAddonInternal(loadedAddon);
addonDB.set(newAddon._key, newAddon);
};
parseTimer.done();
this.addonDB = addonDB;
LOG("Successfully read XPI database");
this.initialized = true;
@ -638,13 +633,18 @@ this.XPIDatabase = {
catch(e) {
// If we catch and log a SyntaxError from the JSON
// parser, the xpcshell test harness fails the test for us: bug 870828
parseTimer.done();
if (e.name == "SyntaxError") {
ERROR("Syntax error parsing saved XPI JSON data");
AddonManagerPrivate.recordSimpleMeasure("XPIDB_startupError", "syntax");
}
else {
ERROR("Failed to load XPI JSON data from profile", e);
AddonManagerPrivate.recordSimpleMeasure("XPIDB_startupError", "other");
}
let rebuildTimer = AddonManagerPrivate.simpleTimer("XPIDB_rebuildReadFailed_MS");
this.rebuildDatabase(aRebuildOnError);
rebuildTimer.done();
}
},
@ -652,14 +652,18 @@ this.XPIDatabase = {
* Upgrade database from earlier (sqlite or RDF) version if available
*/
upgradeDB: function(aRebuildOnError) {
let upgradeTimer = AddonManagerPrivate.simpleTimer("XPIDB_upgradeDB_MS");
try {
let schemaVersion = Services.prefs.getIntPref(PREF_DB_SCHEMA);
if (schemaVersion <= LAST_SQLITE_DB_SCHEMA) {
// we should have an older SQLITE database
this.migrateData = this.getMigrateDataFromSQLITE();
}
// else we've upgraded before but the JSON file is gone, fall through
// and rebuild from scratch
else {
// we've upgraded before but the JSON file is gone, fall through
// and rebuild from scratch
AddonManagerPrivate.recordSimpleMeasure("XPIDB_startupError", "dbMissing");
}
}
catch(e) {
// No schema version pref means either a really old upgrade (RDF) or
@ -668,6 +672,7 @@ this.XPIDatabase = {
}
this.rebuildDatabase(aRebuildOnError);
upgradeTimer.done();
},
/**
@ -675,13 +680,15 @@ this.XPIDatabase = {
* (for example because read permission is denied)
*/
rebuildUnreadableDB: function(aError, aRebuildOnError) {
let rebuildTimer = AddonManagerPrivate.simpleTimer("XPIDB_rebuildUnreadableDB_MS");
WARN("Extensions database " + this.jsonFile.path +
" exists but is not readable; rebuilding in memory", aError);
" exists but is not readable; rebuilding", aError);
// Remember the error message until we try and write at least once, so
// we know at shutdown time that there was a problem
this._loadError = aError;
// XXX TELEMETRY report when this happens?
AddonManagerPrivate.recordSimpleMeasure("XPIDB_startupError", "unreadable");
this.rebuildDatabase(aRebuildOnError);
rebuildTimer.done();
},
/**
@ -692,22 +699,31 @@ this.XPIDatabase = {
* @return Promise<Map> resolves to the Map of loaded JSON data stored
* in this.addonDB; never rejects.
*/
asyncLoadDB: function XPIDB_asyncLoadDB(aDBCallback) {
asyncLoadDB: function XPIDB_asyncLoadDB() {
// Already started (and possibly finished) loading
if (this._dbPromise) {
return this._dbPromise;
}
LOG("Starting async load of XPI database " + this.jsonFile.path);
return this._dbPromise = OS.File.read(this.jsonFile.path).then(
AddonManagerPrivate.recordSimpleMeasure("XPIDB_async_load", XPIProvider.runPhase);
let readOptions = {
outExecutionDuration: 0
};
return this._dbPromise = OS.File.read(this.jsonFile.path, null, readOptions).then(
byteArray => {
LOG("Async JSON file read took " + readOptions.outExecutionDuration + " MS");
AddonManagerPrivate.recordSimpleMeasure("XPIDB_asyncRead_MS",
readOptions.outExecutionDuration);
if (this._addonDB) {
LOG("Synchronous load completed while waiting for async load");
return this.addonDB;
}
LOG("Finished async read of XPI database, parsing...");
let decodeTimer = AddonManagerPrivate.simpleTimer("XPIDB_decode_MS");
let decoder = new TextDecoder();
let data = decoder.decode(byteArray);
decodeTimer.done();
this.parseDB(data, true);
return this.addonDB;
})
@ -973,11 +989,21 @@ this.XPIDatabase = {
this.initialized = false;
if (this._deferredSave) {
AddonManagerPrivate.recordSimpleMeasure(
"XPIDB_saves_total", this._deferredSave.totalSaves);
AddonManagerPrivate.recordSimpleMeasure(
"XPIDB_saves_overlapped", this._deferredSave.overlappedSaves);
AddonManagerPrivate.recordSimpleMeasure(
"XPIDB_saves_late", this._deferredSave.dirty ? 1 : 0);
}
// Make sure any pending writes of the DB are complete, and we
// finish cleaning up, and then call back
this.flush()
.then(null, error => {
ERROR("Flush of XPI database failed", error);
AddonManagerPrivate.recordSimpleMeasure("XPIDB_shutdownFlush_failed", 1);
return 0;
})
.then(count => {
@ -1137,6 +1163,7 @@ this.XPIDatabase = {
// an XPI theme to a lightweight theme before the DB has loaded,
// because we're called from sync XPIProvider.addonChanged
WARN("Synchronous load of XPI database due to getAddonsByType(" + aType + ")");
AddonManagerPrivate.recordSimpleMeasure("XPIDB_lateOpen_byType", XPIProvider.runPhase);
this.syncLoadDB(true);
}
return _filterDB(this.addonDB, aAddon => (aAddon.type == aType));
@ -1152,8 +1179,9 @@ this.XPIDatabase = {
getVisibleAddonForInternalName: function XPIDB_getVisibleAddonForInternalName(aInternalName) {
if (!this.addonDB) {
// This may be called when the DB hasn't otherwise been loaded
// XXX TELEMETRY
WARN("Synchronous load of XPI database due to getVisibleAddonForInternalName");
AddonManagerPrivate.recordSimpleMeasure("XPIDB_lateOpen_forInternalName",
XPIProvider.runPhase);
this.syncLoadDB(true);
}
@ -1225,7 +1253,8 @@ this.XPIDatabase = {
*/
addAddonMetadata: function XPIDB_addAddonMetadata(aAddon, aDescriptor) {
if (!this.addonDB) {
// XXX telemetry. Should never happen on platforms that have a default theme
AddonManagerPrivate.recordSimpleMeasure("XPIDB_lateOpen_addMetadata",
XPIProvider.runPhase);
this.syncLoadDB(false);
}
@ -1371,7 +1400,9 @@ this.XPIDatabase = {
*/
writeAddonsList: function XPIDB_writeAddonsList() {
if (!this.addonDB) {
// Unusual condition, force the DB to load
// force the DB to load
AddonManagerPrivate.recordSimpleMeasure("XPIDB_lateOpen_writeList",
XPIProvider.runPhase);
this.syncLoadDB(true);
}
Services.appinfo.invalidateCachesOnRestart();

View File

@ -998,19 +998,19 @@ function prepare_test(aExpectedEvents, aExpectedInstalls, aNext) {
// Checks if all expected events have been seen and if so calls the callback
function check_test_completed(aArgs) {
if (!gNext)
return;
return undefined;
if (gExpectedInstalls instanceof Array &&
gExpectedInstalls.length > 0)
return;
return undefined;
else for each (let installList in gExpectedInstalls) {
if (installList.length > 0)
return;
return undefined;
}
for (let id in gExpectedEvents) {
if (gExpectedEvents[id].length > 0)
return;
return undefined;
}
return gNext.apply(null, aArgs);
@ -1186,6 +1186,7 @@ if ("nsIWindowsRegKey" in AM_Ci) {
if (value.name == aName)
return value.value;
}
return null;
}
};
@ -1290,7 +1291,7 @@ do_register_cleanup(function addon_cleanup() {
var dirEntries = gTmpD.directoryEntries
.QueryInterface(AM_Ci.nsIDirectoryEnumerator);
var entry;
while (entry = dirEntries.nextFile) {
while ((entry = dirEntries.nextFile)) {
do_throw("Found unexpected file in temporary directory: " + entry.leafName);
}
dirEntries.close();

View File

@ -16,7 +16,7 @@ const IGNORE_PRIVATE = ["AddonAuthor", "AddonCompatibilityOverride",
"registerProvider", "unregisterProvider",
"addStartupChange", "removeStartupChange",
"recordTimestamp", "recordSimpleMeasure",
"getSimpleMeasures"];
"getSimpleMeasures", "simpleTimer"];
function test_functions() {
for (let prop in AddonManager) {