846921 - Add telemetry for per-addon details

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[:Irving Reid (No longer working on Firefox)]

We would like to gather a bunch of per-addon information to help with future efforts.

Specific items to gather are:

- installed packed vs. unpacked
- names of files modified outside addon manager (see bug 810149)
- time required to bootstrap
- time to shut down

Other possible data points:

- version compatibility? (see bug 763243)
- configured to automatically update?
- automatic updates working correctly?

Exact format for the data TBD - would adding a new section be the right way? Would it be OK to use the addon ID as part of the JSON structure, like:

addons: {
  "{a1d3-rest-of-UUID}": {"packed": 0, "bootstrapMS": 125, "shutdown":20},
  "[e-mail]": {...}
}

Comment 1

[Blair McBride [:Unfocused] (UNAVAILABLE)]

A lot of these fit in better with the HealthReport, which is already gathering similar data on individual installed add-ons.

Comment 2

[Gregory Szorc [:gps]]

Here is an example record from FHR:

        "[e-mail]": {
          "userDisabled": false,
          "appDisabled": false,
          "version": "0.7.7",
          "type": "extension",
          "scope": 1,
          "foreignInstall": false,
          "hasBinaryComponents": false,
          "installDay": 15196,
          "updateDay": 15307
        },

This data is somewhat redundant with that in the blocklist ping and is obviously redundant with the update check. Lots of redundancy overall. But, add-on data is also extremely useful for correlation, so I can understand why it needs to be in every payload.

mconnor can address whether adding more add-on metadata to FHR is feasible.

Comment 3

[(dormant account)]

gps, that looks great. We need some more low-level details(eg packed or unpacked, scanned for update in bad ways, etc). Can we use your code by providing a callback to gather extra stuff? Or should we just duplicate this functionality?

Comment 4

[Gregory Szorc [:gps]]

I will almost always say code duplication should be avoided.

I'd feel much better if the code for collecting add-on details lived next to the add-on code in Toolkit, not in /services/healthreport. This has been the original plan all along. FHR supports loading providers via the category manager (https://hg.mozilla.org/mozilla-central/file/af5f267cd6a1/services/healthreport/HealthReportComponents.manifest). The only reason all the providers live in /services/healthreport today is because a) we wanted the code in our module so we could make changes quickly (e.g. if we changed APIs we didn't have to track down multiple module reviewers) b) JS compartment memory overhead (we didn't want to incur loading of extra JSMs at app init time).

I'd still like to continue having the FHR *providers* living in /services/healthreport for these reasons. However, the routine at https://hg.mozilla.org/mozilla-central/file/af5f267cd6a1/services/healthreport/providers.jsm#l695 could be factored out into AddonManager or elsewhere for consumption by both FHR and Telemetry.

Or, you could say "that code is trivial, I'll just copy it" and I wouldn't be too offended :)

Comment 5

[Lawrence Mandel [:lmandel] (use needinfo)]

Taras - You blew away the whiteboard notations that I added in order to setup Scrumbugs for the perf team. :)

Comment 6

[:Irving Reid (No longer working on Firefox)]

Attachment: WIP for a new addonDetails section in telemetry

This still needs changes to about:telemetry to display the contents, and I don't expect that the metrics dashboard will do anything useful with it. It gives us enough that we can make some hadoop jobs to identify which (if any) addons are modifying files inside their install directory, and addons with slow startup or shutdown.

Comment 7

[Nathan Froyd [:froydnj]]

Comment on attachment 729679 [details] [diff] [review]
WIP for a new addonDetails section in telemetry

Review of attachment 729679 [details] [diff] [review]:
-----------------------------------------------------------------

This looks reasonable.  I don't understand why we need to record the _newestFile bits, since this patch doesn't do anything with them.  Or is doing something useful with that still unwritten?

::: toolkit/components/telemetry/TelemetryPing.js
@@ +365,5 @@
> +    try {
> +      let context = Cu.import("resource://gre/modules/XPIProvider.jsm");
> +      return context.XPIProvider.telemetry;
> +    } catch (ex) {
> +      // XXX or would it be better to leave the section out? It shouldn't ever fail...

Either way.  Other sections record empty {} if there's nothing useful.  I think at one point we tried to keep them out, but since everybody puts empty things in anyway... Might as well just put an empty object in and keep things easy.

::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +1316,4 @@
>  
>    if (aFile.isDirectory()) {
>      let entries = aFile.directoryEntries.QueryInterface(Ci.nsIDirectoryEnumerator);
> +    let entry, subName, subTime;

Nit: Could probably move subName and subTime down into the while loop.

@@ +1852,5 @@
>      aLocation.addonLocations.forEach(function(file) {
>        let id = aLocation.getIDForLocation(file);
> +      let modFile, modTime;
> +      let unpacked = 0;
> +      [modFile, modTime] = recursiveLastModifiedTime(file);

FWIW, you can just:

let [modFile, modTime] = recursiveLastModifiedTime(file);

directly.

@@ +3849,5 @@
>      finally {
>        if (aMethod == "shutdown")
>          Components.manager.removeBootstrappedManifestLocation(aFile);
>      }
> +    this._setTelemetry(aId, aMethod + "_MS", new Date() - timeStart);

I'm not familiar with this area of code; are we only calling |callBootstrapMethod| once for every interesting tuple of (|aId|,|aMethod|)?  I see we have manual calls to _setTelemetry several hundred lines above this as well.  Just concerned we're not going to be overwriting things...

I assume the reason we don't have histograms here is because we'd like detailed statistics on individual addons?

Comment 8

[:Irving Reid (No longer working on Firefox)]

Attachment: Gather per-addon details for Telemetry, de-bitrotted and with about:telemetry display

Unless the about:telemetry section needs substantial work, or people think we should track more information in the first landing, I think this is pretty much ready to go.

(In reply to Nathan Froyd (:froydnj) from comment #7)
> Comment on attachment 729679 [details] [diff] [review]
> WIP for a new addonDetails section in telemetry

> This looks reasonable.  I don't understand why we need to record the
> _newestFile bits, since this patch doesn't do anything with them.  Or is
> doing something useful with that still unwritten?

If an addon is found to have been modified outside Firefox, we copy the _newestFile value into a telemetry detail for that addon - check it out: Shut down FF, touch a file in one of your addons, restart, and look at the add-on details in about:telemetry

> Nit: Could probably move subName and subTime down into the while loop.
...
> FWIW, you can just:
> let [modFile, modTime] = recursiveLastModifiedTime(file);
> directly.

Done in several places.

> I'm not familiar with this area of code; are we only calling
> |callBootstrapMethod| once for every interesting tuple of (|aId|,|aMethod|)?
> I see we have manual calls to _setTelemetry several hundred lines above this
> as well.  Just concerned we're not going to be overwriting things...

If a bootstrap addon is enabled / disabled multiple times in one session we'll only capture the last time. This is expected to be rare.

> I assume the reason we don't have histograms here is because we'd like
> detailed statistics on individual addons?

We want the details traceable to a specific addon, and generally a single value is recorded per session for each detail so we'd prefer not to have the overhead of a histogram.

Comment 9

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Comment on attachment 803337 [details] [diff] [review]
Gather per-addon details for Telemetry, de-bitrotted and with about:telemetry display

Review of attachment 803337 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/components/telemetry/TelemetryPing.js
@@ +345,5 @@
>  
> +  getAddonDetails: function getAddonDetails() {
> +    try {
> +      let context = Cu.import("resource://gre/modules/XPIProvider.jsm");
> +      return context.XPIProvider.telemetry;

I have an intense dislike for APIs limited to only one provider - can you make this a general API on AddonManager that can be optionally implemented by any provider, and have the results somehow differentiate between the different providers?

::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +3062,2 @@
>                  modifiedExManifest += 1;
> +                this._setTelemetry(aOldAddon.id, "modifiedExceptInstallRDF", 1);

We already have measurements for modifiedUnpacked, modifiedExceptInstallRDF, and modifiedXPI - albeit at a global level rather than per-addon. Do we really need to keep the global-level measurements if we have per-addon measurements?

@@ +4049,5 @@
>          LOG("Removing manifest for " + aFile.path);
>          Components.manager.removeBootstrappedManifestLocation(aFile);
>        }
>      }
> +    this._setTelemetry(aId, aMethod + "_MS", new Date() - timeStart);

This should be in the finally{} block.

Comment 10

[Nathan Froyd [:froydnj]]

Comment on attachment 803337 [details] [diff] [review]
Gather per-addon details for Telemetry, de-bitrotted and with about:telemetry display

Review of attachment 803337 [details] [diff] [review]:
-----------------------------------------------------------------

I agree with Blair's comments.

::: toolkit/components/telemetry/TelemetryPing.js
@@ +345,5 @@
>  
> +  getAddonDetails: function getAddonDetails() {
> +    try {
> +      let context = Cu.import("resource://gre/modules/XPIProvider.jsm");
> +      return context.XPIProvider.telemetry;

This might go away if/once Blair's comments are addressed, but I dislike importing things in local scopes.  What's the reasoning for doing the import here rather than at global scope?

Comment 11

[Vladan Djeric (:vladan)]

Comment on attachment 803337 [details] [diff] [review]
Gather per-addon details for Telemetry, de-bitrotted and with about:telemetry display

Review of attachment 803337 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/content/aboutTelemetry.js
@@ +535,2 @@
>     */
> +  render: function KeyValueTable_render(aTableID, aMeasurements, keysLabel, valuesLabel) {

- prefix parameter names with "a"
- add the @param definitions in the function comment

@@ +836,5 @@
> +  let addonDetails = ping.addonDetails;
> +  if (Object.keys(addonDetails).length) {
> +    KeyValueTable.render("addon-details-table", addonDetails,
> +                         bundle.GetStringFromName("addonTableID"),
> +                         bundle.GetStringFromName("addonTableDetails"));

let's just always pass the column labels to KeyValueTable.render. So fetch the "Property"/"Value" strings earlier in this function and pass them in calls to KeyValueTable.render. Also remove KeyValuesTable.keysHeaders/valuesHeader

::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +1333,5 @@
>  }
>  
>  /**
> + * Returns the timestamp and leaf file name of the most recently modified
> + * entry in a directory,

Would there be benefit in reporting all the modified filenames/directories (up to some max)?

@@ +1551,5 @@
>    // Keep track of startup phases for telemetry
>    runPhase: XPI_STARTING,
> +  // Keep track of the newest file in each add-on, in case we want to
> +  // report it to telemetry.
> +  _newestFile: {},

rename to _mostRecentlyModifiedFile or something similar (ctime vs mtime)

Comment 12

[:Irving Reid (No longer working on Firefox)]

Attachment: Gather per-addon details for Telemetry, comments incorporated

(In reply to Blair McBride [:Unfocused] from comment #9)
> Comment on attachment 803337 [details] [diff] [review]
> Gather per-addon details for Telemetry, de-bitrotted and with
> about:telemetry display
> 
> Review of attachment 803337 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: toolkit/components/telemetry/TelemetryPing.js
> @@ +345,5 @@
> >  
> > +  getAddonDetails: function getAddonDetails() {
> > +    try {
> > +      let context = Cu.import("resource://gre/modules/XPIProvider.jsm");
> > +      return context.XPIProvider.telemetry;
> 
> I have an intense dislike for APIs limited to only one provider - can you
> make this a general API on AddonManager that can be optionally implemented
> by any provider, and have the results somehow differentiate between the
> different providers?

OK, I routed it through AddonManager / callProviders

> We already have measurements for modifiedUnpacked, modifiedExceptInstallRDF,
> and modifiedXPI - albeit at a global level rather than per-addon. Do we
> really need to keep the global-level measurements if we have per-addon
> measurements?

No, we don't. Removed the global counts.

> @@ +4049,5 @@
> > +    this._setTelemetry(aId, aMethod + "_MS", new Date() - timeStart);
> 
> This should be in the finally{} block.

OK.

(In reply to Nathan Froyd (:froydnj) (AFK 16-20 September) from comment #10)
> Comment on attachment 803337 [details] [diff] [review]
> > +      let context = Cu.import("resource://gre/modules/XPIProvider.jsm");
> > +      return context.XPIProvider.telemetry;
> 
> This might go away if/once Blair's comments are addressed, but I dislike
> importing things in local scopes.  What's the reasoning for doing the import
> here rather than at global scope?

I was following the example of TelemetryTimestamps.jsm in this file. That said, I'm now using AddonManagerPrivate in more than one place so I switched to a global defineLazyModuleGetter.

(In reply to Vladan Djeric (:vladan) from comment #11)
> Comment on attachment 803337 [details] [diff] [review]
> - prefix parameter names with "a"
> - add the @param definitions in the function comment

OK

> @@ +836,5 @@
> > +  let addonDetails = ping.addonDetails;
> > +  if (Object.keys(addonDetails).length) {
> > +    KeyValueTable.render("addon-details-table", addonDetails,
> > +                         bundle.GetStringFromName("addonTableID"),
> > +                         bundle.GetStringFromName("addonTableDetails"));
> 
> let's just always pass the column labels to KeyValueTable.render. So fetch
> the "Property"/"Value" strings earlier in this function and pass them in
> calls to KeyValueTable.render. Also remove
> KeyValuesTable.keysHeaders/valuesHeader

Cleaned this up some, and made KeyValueTable.render return the "table" node so that I could use it in a loop over the possible providers of addon details.

> ::: toolkit/mozapps/extensions/XPIProvider.jsm
> @@ +1333,5 @@
> >  }
> >  
> >  /**
> > + * Returns the timestamp and leaf file name of the most recently modified
> > + * entry in a directory,
> 
> Would there be benefit in reporting all the modified filenames/directories
> (up to some max)?

Perhaps, but it would be a fair bit of work. We'll probably want to manually test the more popular addons this catches in any case, so we'll get a more detailed list from that.

> @@ +1551,5 @@
> rename to _mostRecentlyModifiedFile or something similar (ctime vs mtime)

OK. I took advantage of the opportunity to clean up the way I was deciding how to report modifications; any addon that is modified outside the XPI provider will now report exactly one of "modifiedInstallRDF", "modifiedFile", or "modifiedXPI".

Comment 13

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Comment on attachment 805764 [details] [diff] [review]
Gather per-addon details for Telemetry, comments incorporated

Review of attachment 805764 [details] [diff] [review]:
-----------------------------------------------------------------

(Only looked at the Add-ons Manager changes)

Comment 14

[Vladan Djeric (:vladan)]

Comment on attachment 805764 [details] [diff] [review]
Gather per-addon details for Telemetry, comments incorporated

Review of attachment 805764 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/components/telemetry/TelemetryPing.js
@@ +567,5 @@
>        slowSQL: Telemetry.slowSQL,
>        chromeHangs: Telemetry.chromeHangs,
>        lateWrites: Telemetry.lateWrites,
>        addonHistograms: this.getAddonHistograms(),
> +      addonDetails: this.getAddonDetails(),

Why not call AddonManagerPrivate.getTelemetryDetails() directly?

::: toolkit/content/aboutTelemetry.js
@@ +822,5 @@
>    let simpleMeasurements = sortStartupMilestones(ping.simpleMeasurements);
>    if (Object.keys(simpleMeasurements).length) {
> +    let simpleSection = document.getElementById("simple-measurements");
> +    simpleSection.appendChild(KeyValueTable.render(simpleMeasurements,
> +                                                   keysHeader, valuesHeader));

It might be a bit cleaner to just pass in the target section's ID or element to KeyValueTable.render and have KeyValueTable.render append a table to it

@@ +853,5 @@
> +                             bundle.GetStringFromName("addonTableDetails")));
> +    }
> +  } else {
> +    showEmptySectionMessage("addon-details-section");
> +  }

Could you create a new AddonDetails singleton and have its render method call KeyValueTable.render? That way all the DOM creation code is in the singletons.

Comment 15

[:Irving Reid (No longer working on Firefox)]

Attachment: Per-addon telemetry details, somewhat reworked

As I was working through the last set of comments, I realized that the final telemetry packet would not gather correctly, because the data is gathered after AddonManager is shut down - so iterating over all the loaded providers won't work.

I rearranged things so that the provider can register an object with the AddonManager and then insert telemetry data into that object at will; the data is saved after AM shutdown so that TelemetryPing can still collect it.

I'll post an interdiff as well.

(In reply to Vladan Djeric (:vladan) from comment #14)
> Comment on attachment 805764 [details] [diff] [review]
> Gather per-addon details for Telemetry, comments incorporated
> 
> Review of attachment 805764 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: toolkit/components/telemetry/TelemetryPing.js
> @@ +567,5 @@
> >        slowSQL: Telemetry.slowSQL,
> >        chromeHangs: Telemetry.chromeHangs,
> >        lateWrites: Telemetry.lateWrites,
> >        addonHistograms: this.getAddonHistograms(),
> > +      addonDetails: this.getAddonDetails(),
> 
> Why not call AddonManagerPrivate.getTelemetryDetails() directly?

The intermediate function was left over from when I was demand loading AddonManger, I've removed it.

> ::: toolkit/content/aboutTelemetry.js
> @@ +822,5 @@
> >    let simpleMeasurements = sortStartupMilestones(ping.simpleMeasurements);
> >    if (Object.keys(simpleMeasurements).length) {
> > +    let simpleSection = document.getElementById("simple-measurements");
> > +    simpleSection.appendChild(KeyValueTable.render(simpleMeasurements,
> > +                                                   keysHeader, valuesHeader));
> 
> It might be a bit cleaner to just pass in the target section's ID or element
> to KeyValueTable.render and have KeyValueTable.render append a table to it

It makes using KeyValueTable.render from inside a loop (as I do in AddonDetails.render() much messier; but aside from that, in general I'm not a big fan of methods that "return" their values by side effects, and this use case is a prime example of why I feel that way.

> @@ +853,5 @@
> > +                             bundle.GetStringFromName("addonTableDetails")));
> > +    }
> > +  } else {
> > +    showEmptySectionMessage("addon-details-section");
> > +  }
> 
> Could you create a new AddonDetails singleton and have its render method
> call KeyValueTable.render? That way all the DOM creation code is in the
> singletons.

OK. It could just as easily be a standalone function rather than a singleton object, but I made it an object to match the other cases in this file.

Comment 16

[:Irving Reid (No longer working on Firefox)]

Attachment: Interdiff for reworked addon telemetry patch

Comment 17

[:Irving Reid (No longer working on Firefox)]

I forgot to describe one other change in the latest patch - Vladan had complained on IRC that some of the longer JSON-formatted telemetry fields look bad in about:telemetry. I added a formatter to stringify the JSON data with spaces between top-level elements, so that the browser can line wrap them.

Comment 18

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Comment on attachment 811172 [details] [diff] [review]
Per-addon telemetry details, somewhat reworked

Review of attachment 811172 [details] [diff] [review]:
-----------------------------------------------------------------

(In reply to :Irving Reid from comment #15)
> As I was working through the last set of comments, I realized that the final
> telemetry packet would not gather correctly, because the data is gathered
> after AddonManager is shut down - so iterating over all the loaded providers
> won't work.
> 
> I rearranged things so that the provider can register an object with the
> AddonManager and then insert telemetry data into that object at will; the
> data is saved after AM shutdown so that TelemetryPing can still collect it.

Hmm, don't like this, for a few reasons. If the Add-on Manager is shutdown, I'd rather not have any guarantees that anything will work. It also means we're always collecting data for telemetry, regardless of whether we'll use it or not. And it also limits how we collect data in providers (it's dependent on events - if there's data not associated with events, providers would have to get it on startup).

How about an API like:

AddonManagerPrivate.startTelemetryCollection() - tells all providers to start collecting
AddonManagerPrivate.stopTelemetryCollection() - tells all providers to stop collecting
AddonManager.getTelemetryData() - get collected data from all providers

With AddonManagerInternal.shutdown() sending a "addons-shutdown" notification for TelemetryPing.js to listen to, so data can be fetched before providers are shutdown.

Comment 19

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Comment on attachment 811172 [details] [diff] [review]
Per-addon telemetry details, somewhat reworked

(Bugzilla is hard, lets go shopping.)

Comment 20

[Blair McBride [:Unfocused] (UNAVAILABLE)]

Comment on attachment 811172 [details] [diff] [review]
Per-addon telemetry details, somewhat reworked

Review of attachment 811172 [details] [diff] [review]:
-----------------------------------------------------------------

Discussed this in more detail on IRC - there are a few issues with my proposal in comment 18 that the patch here handles far better - eg, recording during startup() and shutdown().

I do think we eventually need providers to start/stop collecting telemetry data when appropriate, instead of always collecting data. But that would be good for a followup bug.

Comment 21

[Vladan Djeric (:vladan)]

Comment on attachment 811172 [details] [diff] [review]
Per-addon telemetry details, somewhat reworked

Review of attachment 811172 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/content/aboutTelemetry.js
@@ +535,5 @@
> +    if (aObject.length == 0) {
> +      return "[]";
> +    }
> +    output = "[" + JSON.stringify(aObject[0]);
> +    for (let i = 1 ; i < aObject.length ; i++) {

You could also check if i==0 inside the loop instead, but that's just an optional style comment

@@ +545,5 @@
> +  if (keys.length == 0) {
> +    return "{}";
> +  }
> +  output = "{\"" + keys[0] + "\":" + JSON.stringify(aObject[keys[0]]);
> +  for (let i = 1 ; i < keys.length ; i++) {

no spaces before the semi-colon in this loop and loop above

@@ +546,5 @@
> +    return "{}";
> +  }
> +  output = "{\"" + keys[0] + "\":" + JSON.stringify(aObject[keys[0]]);
> +  for (let i = 1 ; i < keys.length ; i++) {
> +    output += ", \"" + keys[i] + "\":" + JSON.stringify(aObject[keys[i]]);

maybe add a space after the semi-colon in the output?

@@ +621,5 @@
> +   * @param aSections Object containing the details sections to render
> +   */
> +  render: function AddonDetails_render(aSections) {
> +    let tableIDTitle = bundle.GetStringFromName("addonTableID");
> +    let tableDetailsTitle = bundle.GetStringFromName("addonTableDetails");

Nit: make the two strings into properties of AddonDetails like the other singletons in this file :)

Comment 22

[:Irving Reid (No longer working on Firefox)]

Pushed https://hg.mozilla.org/integration/fx-team/rev/0a9e2dd65d14

(In reply to Vladan Djeric (:vladan) from comment #21)
> Comment on attachment 811172 [details] [diff] [review]
> Per-addon telemetry details, somewhat reworked

> > +  output = "{\"" + keys[0] + "\":" + JSON.stringify(aObject[keys[0]]);
> > +  for (let i = 1 ; i < keys.length ; i++) {
> > +    output += ", \"" + keys[i] + "\":" + JSON.stringify(aObject[keys[i]]);
> 
> maybe add a space after the semi-colon in the output?

OK, but I used a non-breaking space so that keys and values stay together as the lines wrap.

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/0a9e2dd65d14