810149 - Never recursively scan addon directories on startup

Status: RESOLVED FIXED

(Toolkit :: Add-ons Manager, defect)

Description

[(dormant account)]

At the moment we do recursive scan to figure out extension last modified time. This is especially back for jetpack addons because they have lots of files.

Comment 1

[Dave Townsend [:mossop]]

This could cause bustage when a third-party app or developer changes the extension's files and we don't properly clear the startup cache. I honestly don't know how often that might be a problem but we might want to figure out how we could run some tests like that.

Comment 2

[Blair McBride [:Unfocused] (UNAVAILABLE)]

I had similar worries. We might be able to get away with just scanning install.rdf, and requiring that other vendors *must* update/touch that file when any other file changes. Which really, they should be doing to bump the version string anyway.

In general, recursively scanning all files does seem like a poor tradeoff (in terms of IO), for what should be a rare edge-case.

Comment 3

[(dormant account)]

Blair, can you post the link to the problematic code in question so we can drop in some telemetry to measure the impact of a fix?

Comment 4

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

If necessary, we could just scan install.rdf at startup, and scan recursively much later, in a background thread, to catch any problem with offending add-ons.

Comment 5

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to Taras Glek (:taras) from comment #3)
> Blair, can you post the link to the problematic code in question so we can
> drop in some telemetry to measure the impact of a fix?

This is the call on startup that leads to recursively checking the last modified timestamp:
https://hg.mozilla.org/mozilla-central/file/b857905d82b4/toolkit/mozapps/extensions/XPIProvider.jsm#l2989

The code change would mean replacing the call to recursiveLastModifiedTime, with something that only looked at install.rdf, here:
https://hg.mozilla.org/mozilla-central/file/b857905d82b4/toolkit/mozapps/extensions/XPIProvider.jsm#l1826

Comment 6

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(In reply to David Rajchenbach Teller [:Yoric] from comment #4)
> If necessary, we could just scan install.rdf at startup, and scan
> recursively much later, in a background thread, to catch any problem with
> offending add-ons.

By then it's too late to be useful. We either do this on startup, or not at all.

Saying that, we could potentially do what you suggest, but only use it to report the behavior to AMO and the extension author - so it can be fixed (I'm currently building something specifically for this type of reporting in bug 775253).

Comment 7

[Mike Hommey [:glandium]]

(In reply to Dave Townsend (:Mossop) from comment #1)
> This could cause bustage when a third-party app or developer changes the
> extension's files and we don't properly clear the startup cache.

I think it's fine to break third party apps that would do that. As for developers, if we can solve the problem by adding a pref to disable startup cache for them to use when they want to fiddle with addons in-place.

Comment 8

[Dave Townsend [:mossop]]

(In reply to Mike Hommey [:glandium] from comment #7)
> (In reply to Dave Townsend (:Mossop) from comment #1)
> > This could cause bustage when a third-party app or developer changes the
> > extension's files and we don't properly clear the startup cache.
> 
> I think it's fine to break third party apps that would do that. As for
> developers, if we can solve the problem by adding a pref to disable startup
> cache for them to use when they want to fiddle with addons in-place.

The problem is never that we're breaking third party apps, but that that bustage shows up as bugs in Firefox that the users then blame us for.

Comment 9

[Nagarjuna Varma [:Infinity]]

Attachment: Telemetry Probe

I'm not really sure about the parameters I have specified inside Histogram.json for the Telemetry probe "CHECK_ADDONS_MODIFIED_MS".
Other than that I am hoping this should be fine.

Comment 10

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

Comment on attachment 682709 [details] [diff] [review]
Telemetry Probe

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

Vladan and I have decided to split the work. He'll take this bug, I'll be on the next one.

Comment 11

[Vladan Djeric (:vladan)]

Comment on attachment 682709 [details] [diff] [review]
Telemetry Probe

>diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json
>+  },
>+  "CHECK_ADDONS_MODIFIED_MS": {
>+		"kind": "exponential",
>+		"high": "5000"
>+		"n_buckets": 30,
>+		"description": "Time (ms) it takes to figure out extension last modified time"
>+  },

- Use spaces instead of tabs
- Just a small nitpick: we can probably use fewer buckets here, maybe 10 or 15


>diff --git a/toolkit/mozapps/extensions/XPIProvider.jsm b/toolkit/mozapps/extensions/XPIProvider.jsm
>--- a/toolkit/mozapps/extensions/XPIProvider.jsm
>+++ b/toolkit/mozapps/extensions/XPIProvider.jsm
>+    let telemetry = Services.telemetry;
>+    telemetry.getHistogramById("CHECK_ADDONS_MODIFIED_MS").add(new Date() - telemetryCaptureTime);

You need to break this up a bit and you need a try-except block.. an exception is very unlikely here as long as the histogram exists but we don't want to ever risk exceptions in chrome code

Comment 12

[:Gavin Sharp [email: [e-mail]]]

(In reply to Vladan Djeric (:vladan) from comment #11)
> >+    telemetry.getHistogramById("CHECK_ADDONS_MODIFIED_MS").add(new Date() - telemetryCaptureTime);
> 
> You need to break this up a bit and you need a try-except block.. an
> exception is very unlikely here as long as the histogram exists but we don't
> want to ever risk exceptions in chrome code

That seems far too conservative of a policy. What could realistically cause that to throw an exception? We already call getHistogramById() all over the place without a try/catch, and sprinkling them all over the place without a clear need doesn't sound ideal either.

Comment 13

[Vladan Djeric (:vladan)]

(In reply to :Gavin Sharp (use [e-mail] for email) from comment #12)
> That seems far too conservative of a policy. What could realistically cause
> that to throw an exception? We already call getHistogramById() all over the
> place without a try/catch, and sprinkling them all over the place without a
> clear need doesn't sound ideal either.

Maybe you're right. The histogram name would have to by typo-ed in the getHistogramById call or the histogram would have to be missing or contain incorrect parameters, and I guess in those cases it might be preferable to fail visibly.

Comment 14

[Vladan Djeric (:vladan)]

Nagarjuna, can you make the changes above and we'll get this landed :)

Comment 15

[Nagarjuna Varma [:Infinity]]

Attachment: Telemetry Probe

Sorry vlad! Was kinda caught up with some work at uni (don't get me started) ! Hope this is fine!

PS Sorry for the relatively low metadata associated with the patch...my MQ has gone for a toss. Fixing it!

Comment 16

[Vladan Djeric (:vladan)]

Comment on attachment 685184 [details] [diff] [review]
Telemetry Probe

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

Comment 17

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/4af18f114939

Comment 18

[Vladan Djeric (:vladan)]

Reopening this bug as we have only landed the probe, not the fix

Comment 19

[Ed Morley [:emorley]]

(In reply to Vladan Djeric (:vladan) from comment #18)
> Reopening this bug as we have only landed the probe, not the fix

To prevent the merge tool from closing bugs, you can use [leave open] in the bug whiteboard :-)

Comment 20

[(dormant account)]

Given that we only have this data for the nightly channel(thus less addons), it  be can amazingly slow to do this check. http://is.gd/iO7VnY over ~6.5% startups take over 775ms.

Thanks for the probe, Infinity.

Comment 21

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

Infinity, Taras and Vladan asked me to look into this as well. I have some ideas for additional telemetry probes - email me or catch me on IRC (irving in #perf)

What I'm thinking of are:

* Count of packed (xpi) vs. unpacked extensions

* Extensions that are discovered to have updated file timestamps at startup (names if possible, otherwise count)

* Unpacked extensions where other files are updated but install.rdf is not (name if possible, else count)

* whether the extension DB needed to be updated at startup, and (if we can figure it out) the reason why

Comment 22

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

When we update the plugin DB at startup time, we run the entire scan a second time at http://dxr.mozilla.org/mozilla-central/toolkit/mozapps/extensions/XPIProvider.jsm.html#l2895 (hopefully faster because all the directories should be in the OS disk cache)

Comment 23

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

(In reply to Mike Hommey [:glandium] from comment #7)
> (In reply to Dave Townsend (:Mossop) from comment #1)
> > This could cause bustage when a third-party app or developer changes the
> > extension's files and we don't properly clear the startup cache.
> 
> I think it's fine to break third party apps that would do that. As for
> developers, if we can solve the problem by adding a pref to disable startup
> cache for them to use when they want to fiddle with addons in-place.

Is the --purgecaches command line option good enough for that, or do we really need a pref?

Comment 24

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

Based on conversations with Vladan and Taras, I'm going to draft a patch that uses a pref to choose either complete scan or check only install.rdf

Comment 25

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

Attachment: Control whether to recursively scan unpacked addons with a pref

This patch requires the telemetry probe patch from bug 810146 be applied first.

For now, the default is to do the complete scan (existing behaviour); you need to manually set the "extensions.scanUnpacked" preference to false to change to not-scanning. I still check the timestamp on the root directory (for unpacked) or XPI file (packed), mostly to help generate the telemetry for 810146.

Comment 26

[Dave Townsend [:mossop]]

Comment on attachment 706059 [details] [diff] [review]
Control whether to recursively scan unpacked addons with a pref

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

::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +1836,5 @@
> +      if (scanUnpacked)
> +        state.mtime = recursiveLastModifiedTime(file);
> +      else
> +        // get the mtime of the .xpi file or parent directory
> +        state.mtime = file.lastModifiedTime;

Certain filesystems (notably FAT) don't alter the modification time of a directory when its contents change (the whole reason we do a recursive scan). If the extension is unpacked you should at least use the install.rdf modification time.

Comment 27

[(dormant account)]

Comment on attachment 706059 [details] [diff] [review]
Control whether to recursively scan unpacked addons with a pref

I agree with Dave about not relying on direction mod times for anything. I think strictly checking install.rdf is the way go.

Comment 28

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

Attachment: Control whether to recursively scan unpacked addons with a pref (v2)

Good point about the directory modification time. I've reorganized the logic and added some comments to make it more obvious what timestamps we're using for what purpose, and to not use the directory timestamp.

Comment 29

[Dave Townsend [:mossop]]

Comment on attachment 706512 [details] [diff] [review]
Control whether to recursively scan unpacked addons with a pref (v2)

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

::: toolkit/mozapps/extensions/XPIProvider.jsm
@@ +1838,5 @@
>        };
> +
> +      // the logic we want here is:
> +      // if scan, mod time is recursive and rdfTime is remembered for the unpacked addon telemetry
> +      // if !scan, mod time is: install.rdf if unpacked, foo.xpi if packed

s/scan/scanUnpacked/
s/mod time/mtime/

@@ +1860,5 @@
> +          // this is an unpacked extension
> +          state.mtime = rdfTime;
> +        else
> +          // get the mtime of the .xpi file
> +          state.mtime = file.lastModifiedTime;

By not setting state.rdfTime in this path you're messing up telemetry readings for unpacked add-ons. Just always set it outside of the if blocks.

@@ +1880,5 @@
>     */
>    getInstallLocationStates: function XPI_getInstallLocationStates() {
>      let states = [];
> +    let scanUnpacked = Prefs.getBoolPref(PREF_XPI_SCAN_UNPACKED, true);
> +    

Nit: whitespace

Comment 30

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

Attachment: Control whether to recursively scan unpacked addons with a pref (v3)

Fixed :mossop's comments.

Based on a conversation with Vladan, we want to put this on hold until we get a clearer picture from the telemetry probes in bug 810146 before we make changes to directory scanning.

Comment 31

[Kris Maglione [:kmag]]

Let's use add-on signing as a way to make this happen. Signed add-ons should not be allowed to modify their contents, so we have the option of either enforcing that via the developer agreement, or checking the timestamp of the manifest rather than recursively scanning.

We'll theoretically be scanning for checksum mismatches in the background after startup, so any add-ons which don't match their signatures will be disabled in any case.

There's still the question of developer workflow, but it's a much easier one to solve than the general case.

Comment 32

[Avi Halachmi (:avih)]

(In reply to Kris Maglione [:kmag] from comment #31)
> Let's use add-on signing as a way to make this happen.
> ...
> There's still the question of developer workflow, but it's a much easier one
> to solve than the general case.

Are you saying we should switch to signed addons in order to never scan recursively?

Signed addons has a very big effect on developers, and a decision to move to signed addons policy should not be based solely, or at all, on a need to never scan recursively IMO.

Such a big move needs much wider consensus, or at the very least IMO some proper discussion.

Comment 33

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

(In reply to Avi Halachmi (:avih) from comment #32)
> Are you saying we should switch to signed addons in order to never scan
> recursively?

It's the other way around. We're moving to signed add-ons, so that can be used to avoid the recursive scan.

> Signed addons has a very big effect on developers, and a decision to move to
> signed addons policy should not be based solely, or at all, on a need to
> never scan recursively IMO.
> 
> Such a big move needs much wider consensus, or at the very least IMO some
> proper discussion.

The discussion is happening here: https://groups.google.com/forum/#!forum/mozilla.addons.user-experience. It should move to a broader audience soon.

Comment 34

[Andrew Swan [:aswan]]

This is irrelevant now that we (mostly) don't support unpacked extensions.
We have related issues about fixing other aspects of addon manager startup, but I think this can be safely closed.

Comment 35

[Kris Maglione [:kmag]]

I actually fixed this ages ago.