Closed
Bug 810146
Opened 12 years ago
Closed 12 years ago
Add telemetry for addon manager startup times, unpacked add-ons and various changes detected at startup
Categories
(Toolkit :: Add-ons Manager, defect)
Tracking
()
RESOLVED
FIXED
mozilla21
People
(Reporter: taras.mozilla, Assigned: Irving)
References
(Blocks 1 open bug)
Details
(Whiteboard: [mentor=Yoric][lang=js])
Attachments
(1 file, 6 obsolete files)
No description provided.
Reporter | ||
Updated•12 years ago
|
Summary: Collect telemetry to figure out proprotion of addons that are extracted → Collect telemetry to figure out proportion of addons that are extracted
Reporter | ||
Updated•12 years ago
|
Blocks: start-faster
Comment 1•12 years ago
|
||
As mentioned on IRC, we can get a decent amount of this data from AMO's database already (hi Jorge!).
For actual real-world data, I was expecting to gather this via FHR.
Reporter | ||
Comment 2•12 years ago
|
||
(In reply to Blair McBride (:Unfocused) from comment #1)
> As mentioned on IRC, we can get a decent amount of this data from AMO's
> database already (hi Jorge!).
>
> For actual real-world data, I was expecting to gather this via FHR.
At the most basic level, we want to know what percentage of installed addons is uncompressed and out of the uncompressed addons what is the distribution of the number of files in those addons.
Reporter | ||
Updated•12 years ago
|
Flags: needinfo?(jorge)
Comment 3•12 years ago
|
||
The Add-ons MXR only shows up to 1000 results, so I don't know the exact number, but it's probably high:
https://mxr.mozilla.org/addons/search?string=unpack%3Etrue&find=\.rdf&findi=\.rdf&filter=^[^\0]*%24&hitlimit=&tree=addons
For more detailed information, I think you would need to ask the AMO people to give you a copy of the file repo so you can clone it and run tests locally.
Flags: needinfo?(jorge)
Updated•12 years ago
|
Assignee: nobody → junky.argonaut
Updated•12 years ago
|
Whiteboard: [mentor=Yoric][lang=js]
Comment 4•12 years ago
|
||
For reference, I believe that "unpack" is detected here: http://dxr.mozilla.org/mozilla-central/toolkit/mozapps/extensions/XPIProvider.jsm.html#l723
Comment 5•12 years ago
|
||
Is it, but that happens every time an add-ons manifest is read for whatever reason. Which includes:
* Add-on installs (including cancelled installs!)
* Add-on updates
* Every add-on any time we bump the database schema version (happens every now and then)
* Every add-on after the database has been corrupted (should be extremely rare)
So, what do we want to measure here?
* Add-on installs? That won't get already installed add-ons
* Add-on updates? That biases the results hugely towards add-ons with regular updates
* A snapshot of installed add-ons? This seems best to me.
Telemetry already gets add-on data in snapshots, via XPIProvider.addAddonsToCrashReporter(). But adding this kinda of data there without unnecessarily opening the database (which we need to avoid) would require bug 793143.
Alternatively, we could do it during the background update check - which makes it easier, as the DB has to be open for that anyway (and I'm already adding some reporting there in bug 775253). There's a bit of a discrepancy between that and the data added to telemetry via addAddonsToCrashReporter() however (which happens on startup).
Comment 6•12 years ago
|
||
Doing this during the background update check sounds fine. Is the "unpack" information available during this check?
Assignee | ||
Comment 7•12 years ago
|
||
Based on some ideas posted to bug 810149, but this bug is specifically about telemetry so it made sense to me to post it here.
Attachment #694968 -
Flags: review?(vdjeric)
Attachment #694968 -
Flags: review?(bmcbride)
Comment 8•12 years ago
|
||
Comment on attachment 694968 [details] [diff] [review]
Add telemetry for unpacked add-ons and changes detected at start-up
>+ "ADDONS_INSTALLED_UNPACKED": {
>+ "kind": "enumerated",
>+ "n_values": "16",
>+ "description": "Count of unpacked extensions found during startup scan"
>+ },
I think you want a linear histogram here, enum histograms are used for storing C-style enums. More detailed description here: https://developer.mozilla.org/en-US/docs/Performance/Adding_a_new_Telemetry_probe
>+ "ADDONS_MODIFIED_UNPACKED": {
>+ "kind": "enumerated",
>+ "n_values": "6",
>+ "description": "Count of unpacked extensions where files in the extension directory were modified after the last database update"
>+ },
Do we really need this histogram? ADDONS_INSTALLED_UNPACKED will give us an idea of the fraction of profiles with unpacked extensions and ADDONS_MODIFIED_EX_MANIFEST will tell us how safe it is to skip over recursing for mtimes when install.rdf hasn't been modified.
>+ "ADDONS_MODIFIED_EX_MANIFEST": {
>+ "kind": "enumerated",
>+ "n_values": "6",
>+ "description": "Count of unpacked extensions where other files, but not install.rdf, were modified after the last database update"
>+ },
Nit: EX_ is a bit ambiguous, let's call this ADDONS_MODIFIED_EXCEPT_MANIFEST or something
>+ "ADDONS_MODIFIED_XPI": {
>+ "kind": "enumerated",
>+ "n_values": "6",
>+ "description": "Count of packed extensions where the XPI was modified after the last database update"
>+ },
Are you planning to change how we handle packed extensions?
>+ // Tell Telemetry what we did
>+ Services.telemetry.getHistogramById("ADDONS_MODIFIED_UNPACKED").add(modifiedUnpacked);
>+ Services.telemetry.getHistogramById("ADDONS_MODIFIED_EX_MANIFEST").add(modifiedExManifest);
>+ Services.telemetry.getHistogramById("ADDONS_MODIFIED_XPI").add(modifiedXPI);
We shouldn't store a "0" value in ADDONS_MODIFIED_EX_MANIFEST unless an addon was modified "externally" & install.rdf was also modified. So we should make sure modifiedUnpacked > 0 before recording modifiedExManifest in Telemetry
>+ else {
>+ // submit default values for the telemetry info processFileChanges would have produced
>+ Services.telemetry.getHistogramById("ADDONS_MODIFIED_UNPACKED").add(0);
>+ Services.telemetry.getHistogramById("ADDONS_MODIFIED_EX_MANIFEST").add(0);
>+ Services.telemetry.getHistogramById("ADDONS_MODIFIED_XPI").add(0);
>+ }
In this case, we shouldn't record anything in Telemetry if we get an error. It might skew the data
Attachment #694968 -
Flags: review?(vdjeric)
Comment 9•12 years ago
|
||
(In reply to Vladan Djeric (:vladan) from comment #8)
> Comment on attachment 694968 [details] [diff] [review]
> Add telemetry for unpacked add-ons and changes detected at start-up
>
> >+ "ADDONS_INSTALLED_UNPACKED": {
> >+ "kind": "enumerated",
> >+ "n_values": "16",
> >+ "description": "Count of unpacked extensions found during startup scan"
> >+ },
>
> I think you want a linear histogram here, enum histograms are used for
> storing C-style enums
I spoke to Nathan and found out enumerated histograms are the intended way to represent linear histograms with buckets 0, 1...N. His histogram-generation script will assert if a linear histogram is used for this
Assignee | ||
Comment 10•12 years ago
|
||
Based on conversation with Vladan, added a telemetry probe for total add-on manager start up time.
Removed the sending of zero values for modified add-ons, in the case where no modified add-ons were detected at start up time.
The reason for keeping all the other probes is to give a better picture of overall add-on manager start up activity. While the immediate concern in bug 810149 is to avoid scanning the entire unpacked add-on directory tree, we also incur substantial start-up costs when add-ons are modified by external processes so it would be good to know how often this happens.
Assignee: junky.argonaut → irving
Attachment #694968 -
Attachment is obsolete: true
Status: NEW → ASSIGNED
Attachment #694968 -
Flags: review?(bmcbride)
Attachment #699956 -
Flags: feedback?(vdjeric)
Comment 11•12 years ago
|
||
Comment on attachment 699956 [details] [diff] [review]
Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v2)
This looks good. Some thoughts:
1) I think the "0" entry behavior for the histograms is still unintuitive. For example, ADDONS_MODIFIED_XPI will receive a 0 entry only if an *unpacked* histogram is modified. However, I suspect getting the "0" measurements perfectly right might be more work than benefit + we only really care about the MODIFIED_UNPACKED and MODIFIED_XPI histograms for studying raw pings and for that case, we are solely interested in the non-zero entries for explaining slow statups
2) I think your histograms would report disabled addons, but I don't think this is something we need to worry about
3) This is a nitpick, but I would like ADDONS_MODIFIED_EXCEPT_MANIFEST to only store a "0" entry when modifiedUnpacked > 0 instead of whenever any extension has changed. The difference is that we'll be able to figure out at a glance from Telemetry Dashboard what fraction of "in-place updates" of unpacked extensions are well-behaved.
Attachment #699956 -
Flags: feedback?(vdjeric) → feedback+
Assignee | ||
Comment 12•12 years ago
|
||
(In reply to Vladan Djeric (:vladan) from comment #11)
> 2) I think your histograms would report disabled addons, but I don't think
> this is something we need to worry about
As far as I can tell, we do quite a bit of work at start-up time even if the modified add-on is disabled or invisible, so I think counting them is what we want.
Per discussion with Vladan, the ADDONS_MODIFIED_EXCEPT_INSTALL_RDF only registers a 0 value when we detect a modified, unpacked addon so that the interpretation of that probe is that the number of zeros is the number of "safe" startups (where we would have been OK to only check install.rdf), and the number of non-zero is the number of potentially unsafe.
Attachment #699956 -
Attachment is obsolete: true
Attachment #703007 -
Flags: review?(dtownsend+bugmail)
Reporter | ||
Comment 13•12 years ago
|
||
I would prefer to have addon startup(and possibly other measures) as simpleMeasures.
Reporter | ||
Comment 14•12 years ago
|
||
(In reply to Taras Glek (:taras) from comment #13)
> I would prefer to have addon startup(and possibly other measures) as
> simpleMeasures.
we report all of our other startup measures that way and it gives a bit more precisions + results in a smaller ping packet.
Comment 15•12 years ago
|
||
Comment on attachment 703007 [details] [diff] [review]
Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v3)
Review of attachment 703007 [details] [diff] [review]:
-----------------------------------------------------------------
::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +1837,5 @@
> + // get the install.rdf update time, if any
> + file.append(FILE_INSTALL_MANIFEST);
> + let rdfTime = file.lastModifiedTime;
> + addonStates[id].rdfTime = rdfTime;
> + this.unpackedAddons += 1;
Seems like you could do this file stat as a part of recursiveLastModifiedTime rather than doing it a second time again. Not totally necessary but I dislike adding explicit overhead to something we're trying to measure.
@@ +2870,5 @@
> + modifiedExManifest += 1;
> + }
> + else if (aOldAddon.updateDate != addonState.mtime) {
> + modifiedXPI += 1;
> + }
You should ignore the cases where (aOldAddon.id in aManifests[installLocation.name]) as those mark known installs/updates through the UI and so are going to drown out the more interesting information. Or maybe track them separately I guess.
Attachment #703007 -
Flags: review?(dtownsend+bugmail) → review+
Assignee | ||
Comment 16•12 years ago
|
||
(In reply to Dave Townsend (:Mossop) from comment #15)
> Comment on attachment 703007 [details] [diff] [review]
> Add telemetry for add on manager startup time, count unpacked and changed
> add-ons at startup (v3)
>
> Review of attachment 703007 [details] [diff] [review]:
> -----------------------------------------------------------------
>
> ::: toolkit/mozapps/extensions/XPIProvider.jsm
> @@ +1837,5 @@
> > + // get the install.rdf update time, if any
> > + file.append(FILE_INSTALL_MANIFEST);
> > + let rdfTime = file.lastModifiedTime;
> > + addonStates[id].rdfTime = rdfTime;
> > + this.unpackedAddons += 1;
>
> Seems like you could do this file stat as a part of
> recursiveLastModifiedTime rather than doing it a second time again. Not
> totally necessary but I dislike adding explicit overhead to something we're
> trying to measure.
We're hoping to get rid of recursiveLastModifiedTime, so I didn't want to make it more complex. The relevant bits should still be in the buffer cache so the extra call shouldn't need to wait for I/O.
> @@ +2870,5 @@
> > + modifiedExManifest += 1;
> > + }
> > + else if (aOldAddon.updateDate != addonState.mtime) {
> > + modifiedXPI += 1;
> > + }
>
> You should ignore the cases where (aOldAddon.id in
> aManifests[installLocation.name]) as those mark known installs/updates
> through the UI and so are going to drown out the more interesting
> information. Or maybe track them separately I guess.
Based on some manual testing, addons changed in the application, using the add-on manager, don't show up in these counts (I checked both a restartless and a restart-required addon)
Assignee | ||
Comment 17•12 years ago
|
||
Convert telemetry from histograms to simple measures, and use start/end timestamps for startup timing, based on suggestion from Taras.
The about.telemetry information recorded now looks like this:
Simple Measurements
Click to collapse section
Property Value
start 17
main 179
startupCrashDetectionBegin 857
AMI_startup_begin 918
XPI_startup_begin 1044
XPI_bootstrap_addons_begin 1143
XPI_bootstrap_addons_end 1983
XPI_startup_end 1983
AMI_startup_end 1984
createTopLevelWindow 2795
firstPaint 5291
delayedStartupStarted 5293
firstLoadURI 5295
sessionRestoreInitialized 5520
sessionRestoreRestoring 5539
sessionRestored 6532
delayedStartupFinished 6698
startupCrashDetectionEnd 45422
uptime 20
addonManager {"modifiedUnpacked":1,"modifiedExceptInstallRDF":0,"modifiedXPI":1,"installedUnpacked":2}
startupInterrupted 0
debuggerAttached 0
js {"e4x":0,"setProto":0,"customIter":1}
shutdownDuration 6259
savedPings 1
Attachment #703007 -
Attachment is obsolete: true
Attachment #705920 -
Flags: feedback?(taras.mozilla)
Comment 18•12 years ago
|
||
Comment on attachment 705920 [details] [diff] [review]
Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v4)
Taras asked me to give feedback on this since he's busy. You'll still need r+ from a frontend person
>+ try {
>+ let o = {};
>+ Cu.import("resource://gre/modules/AddonManager.jsm", o);
>+ ret.addonManager = o.AddonManagerPrivate.getSimpleMeasures();
>+ } catch (ex) {}
Nit: use a more descriptive variable name
>+ timestamp: function AMI_timestamp(name, value) {
>+ this.TelemetryTimestamps.add(name, value);
>+ },
>+
Rename the functions to start with a verb, e.g. recordTimestamp. Same with "simpleMeasure"
>+ if (modifiedUnpacked > 0)
>+ AddonManagerPrivate.simpleMeasure("modifiedExceptInstallRDF", modifiedExManifest);
I think we're putting curlies around single-line if-statements now
Attachment #705920 -
Flags: feedback?(taras.mozilla) → feedback+
Updated•12 years ago
|
Attachment #705920 -
Flags: review?(dtownsend+bugmail)
Comment 19•12 years ago
|
||
(In reply to Vladan Djeric (:vladan) from comment #18)
> Comment on attachment 705920 [details] [diff] [review]
> Add telemetry for add on manager startup time, count unpacked and changed
> add-ons at startup (v4)
> >+ if (modifiedUnpacked > 0)
> >+ AddonManagerPrivate.simpleMeasure("modifiedExceptInstallRDF", modifiedExManifest);
>
> I think we're putting curlies around single-line if-statements now
Not in this file we're not.
Assignee | ||
Comment 20•12 years ago
|
||
(In reply to Dave Townsend (:Mossop) from comment #19)
> (In reply to Vladan Djeric (:vladan) from comment #18)
> > I think we're putting curlies around single-line if-statements now
>
> Not in this file we're not.
/me takes cover
(In reply to Vladan Djeric (:vladan) from comment #18)
> >+ try {
> >+ let o = {};
> >+ Cu.import("resource://gre/modules/AddonManager.jsm", o);
> >+ ret.addonManager = o.AddonManagerPrivate.getSimpleMeasures();
> >+ } catch (ex) {}
>
> Nit: use a more descriptive variable name
It's exactly the same as the preceding five lines, so I'm inclined to leave it as is.
> Rename the functions to start with a verb, e.g. recordTimestamp. Same with
> "simpleMeasure"
OK.
Attachment #705920 -
Attachment is obsolete: true
Attachment #705920 -
Flags: review?(dtownsend+bugmail)
Attachment #706404 -
Flags: review?(dtownsend+bugmail)
Comment 21•12 years ago
|
||
Comment on attachment 706404 [details] [diff] [review]
Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v5)
Review of attachment 706404 [details] [diff] [review]:
-----------------------------------------------------------------
::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +2923,5 @@
> changed = removeMetadata(aLocation, aOldAddon) || changed;
> }, this);
> }, this);
>
> + // Tell Telemetry what we did
s/did/found/
Attachment #706404 -
Flags: review?(dtownsend+bugmail) → review+
Assignee | ||
Comment 22•12 years ago
|
||
Comment 23•12 years ago
|
||
Backed out for mass bustage.
https://hg.mozilla.org/integration/mozilla-inbound/rev/0c45e6378f1f
Logs available here:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=4a271b44cbfe
Comment 24•12 years ago
|
||
(Also, when you re-land, be sure to include the reviewer in the commit message.)
Assignee | ||
Comment 25•12 years ago
|
||
Requesting re-review on account of moving TelemetryTimestamps.jsm from browser/modules to toolkit/modules to fix Android bustage; also fix spurious test failures on desktop.
Attachment #706404 -
Attachment is obsolete: true
Attachment #707982 -
Flags: review?(dtownsend+bugmail)
Comment 26•12 years ago
|
||
Try run for e5f8e169784a is complete.
Detailed breakdown of the results available here:
https://tbpl.mozilla.org/?tree=Try&rev=e5f8e169784a
Results (out of 50 total builds):
success: 44
warnings: 6
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/ireid@mozilla.com-e5f8e169784a
Comment 27•12 years ago
|
||
Comment on attachment 707982 [details] [diff] [review]
Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v6)
Can you move browser_TelemetryTimestamps.js as well as the module please.
Attachment #707982 -
Flags: review?(dtownsend+bugmail) → review-
Assignee | ||
Comment 28•12 years ago
|
||
Moved the browser chrome mochitest browser_TelemetryTimestamps.js to toolkit/modules/tests
This test should probably be rewritten as an xpcshell test; the only bit of real browser environment it depends on is to check that one of the startup timestamp entries exists.
Unfortunately bug 809920 got in the way of using xpcshell, so this patch leaves it as a browser chrome test.
Attachment #707982 -
Attachment is obsolete: true
Attachment #709163 -
Flags: review?(dtownsend+bugmail)
Assignee | ||
Updated•12 years ago
|
Updated•12 years ago
|
Attachment #709163 -
Flags: review?(dtownsend+bugmail) → review+
Assignee | ||
Comment 29•12 years ago
|
||
Comment 30•12 years ago
|
||
Status: ASSIGNED → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla21
Updated•12 years ago
|
Summary: Collect telemetry to figure out proportion of addons that are extracted → Add telemetry for addon manager startup times, unpacked add-ons and various changes detected at startup
You need to log in
before you can comment on or make changes to this bug.
Description
•