810146 - Add telemetry for addon manager startup times, unpacked add-ons and various changes detected at startup

Status: RESOLVED FIXED

(Toolkit :: Add-ons Manager, defect)

Comment 1

[Blair McBride [:Unfocused] (UNAVAILABLE)]

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.

Comment 2

[(dormant account)]

(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.

Comment 3

[Jorge Villalobos [:jorgev] (he/him)]

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.

Comment 4

[David Teller [:Yoric] - still alive but not very active]

For reference, I believe that "unpack" is detected here: http://dxr.mozilla.org/mozilla-central/toolkit/mozapps/extensions/XPIProvider.jsm.html#l723

Comment 5

[Blair McBride [:Unfocused] (UNAVAILABLE)]

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

[David Teller [:Yoric] - still alive but not very active]

Doing this during the background update check sounds fine. Is the "unpack" information available during this check?

Comment 7

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

Attachment: Add telemetry for unpacked add-ons and changes detected at start-up

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.

Comment 8

[Vladan Djeric (:vladan)]

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

Comment 9

[Vladan Djeric (:vladan)]

(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

Comment 10

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

Attachment: Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v2)

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.

Comment 11

[Vladan Djeric (:vladan)]

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.

Comment 12

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

Attachment: Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v3)

(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.

Comment 13

[(dormant account)]

I would prefer to have addon startup(and possibly other measures) as simpleMeasures.

Comment 14

[(dormant account)]

(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

[Dave Townsend [:mossop]]

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.

Comment 16

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

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

Comment 17

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

Attachment: Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v4)

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

Comment 18

[Vladan Djeric (:vladan)]

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

Comment 19

[Dave Townsend [:mossop]]

(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.

Comment 20

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

Attachment: Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v5)

(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.

Comment 21

[Dave Townsend [:mossop]]

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/

Comment 22

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/4a271b44cbfe

Comment 23

[Ryan VanderMeulen [:RyanVM]]

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

[Daniel Holbert [:dholbert]]

(Also, when you re-land, be sure to include the reviewer in the commit message.)

Comment 25

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

Attachment: Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v6)

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.

Comment 26

[Mozilla RelEng Bot]

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/[e-mail]-e5f8e169784a

Comment 27

[Dave Townsend [:mossop]]

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.

Comment 28

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

Attachment: Add telemetry for add on manager startup time, count unpacked and changed add-ons at startup (v7)

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.

Comment 29

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

Inbound: https://hg.mozilla.org/integration/mozilla-inbound/rev/171c0078dc87

Comment 30

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/171c0078dc87