401229 - Extension manager is flush happy

Status: RESOLVED FIXED

(Toolkit :: Add-ons Manager, defect)

Description

[Dave Townsend [:mossop]]

Following on from bug 396695 comment 44 we seem to be flushing the extensions datasource an awful low, often on startup. I'm going to work on some fixes to reduce the number of flushes while keeping things safe and I also have a plan that may slightly improve the responsiveness of the UI.

A few metrics with things the way they are now:

Installing a new extension (before restart), 13 flushes. During the restart another 4.
Installing an upgrade to an extension (before restart), 13 flushes. During the restart another 14.
Performing an update check for an extension, 3 or 4 if an update is found (that is per extension).

Disturbingly running a new build of firefox (version number didn't change) in a profile that last had an old build run (it detected the 2 app addons as changed but none others), 45 flushes.

Comment 1

[Dave Townsend [:mossop]]

(In reply to comment #0)
> Disturbingly running a new build of firefox (version number didn't change) in a
> profile that last had an old build run (it detected the 2 app addons as changed
> but none others), 45 flushes.

This is 18 flushes per detected changed addon (7 in _upgradeItem, 10 in _configureForthcomingItem, 1 in _addItemMetadata) followed by 9 flushes setting appDisabled to null (which it already was in the first place) on every installed addon.

Comment 2

[Dave Townsend [:mossop]]

Attachment: rough first cut

I haven't properly checked over this so not requesting review just yet but I don't know what you think of this as a plan Rob?

Basically it changes a number of calls to setItemProperty ro just _setProperty with a single Flush, then for common operations that really should flush at the end like _configureForthcomingItem, _upgradeItem and the mail startup paths surround everything in an updatebatch, then put locks in the datasource so it doesn't flush during an updatebatch, just remembers that one has been requested and does it at the end of the batch.

This currently drops the number of flushes on startup to generally 1 if any in-app changes have been made, or 2 if file changes are detected. An install before restart is 4 flushes

Comment 3

[Dave Townsend [:mossop]]

Looking at actual metrics from dtrace this is only incurring a very minor hit in comparison with the rest of the time spent in the EM during startup so I don't believe it is worth fixing in this way.

Comment 4

[Dave Townsend [:mossop]]

Fixing this would greatly alleviate bug 431065

Comment 5

[Dave Townsend [:mossop]]

Attachment: patch rev 1

This adds an explicit block to flushing during the startup sequence, only performing the flushes at the end if necessary. It also adds a setItemProperties method that can be used to set multiple properties with only a single flush at the end and is used in preference to a flush per property in various places.

Comment 6

[Robert Strong (they/them - no direct email)]

Dave, not sure but does it make sense to make sure everything has been flushed in _shutdown() just in case?

Comment 7

[Dave Townsend [:mossop]]

Attachment: patch rev 2

Certainly no harm in it.

Comment 8

[Robert Strong (they/them - no direct email)]

Comment on attachment 330926 [details] [diff] [review]
patch rev 2

This looks good... just a few nits

>diff --git a/toolkit/mozapps/extensions/src/nsExtensionManager.js.in b/toolkit/mozapps/extensions/src/nsExtensionManager.js.in
>--- a/toolkit/mozapps/extensions/src/nsExtensionManager.js.in
>+++ b/toolkit/mozapps/extensions/src/nsExtensionManager.js.in
>@@ -172,16 +172,20 @@ var gConsole              = null;
> var gConsole              = null;
> var gInstallManifestRoot  = null;
> var gVersionChecker       = null;
> var gLoggingEnabled       = null;
> var gCheckCompatibility   = true;
> var gCheckUpdateSecurity  = true;
> var gLocale               = "en-US";
> var gFirstRun             = false;
>+
nit: the vars aren't grouped by use currently but I could go either way with this.

>+var gAllowFlush           = true;
>+var gDSNeedsFlush         = false;
>+var gManifestNeedsFlush   = false;

>@@ -2656,16 +2660,34 @@ ExtensionManager.prototype = {
>     param.AppendElement(arg);
>     ww.openWindow(null, EMURL, null, EMFEATURES, param);
>   },
> 
>   /**
>    * Clean up on application shutdown to avoid leaks.
>    */
>   _shutdown: function() {
>+    if (!gAllowFlush) {
>+      // Something went wrong and there are potentially flushes pending.
>+      try {
>+        gAllowFlush = true;
>+        if (gManifestNeedsFlush) {
>+          gManifestNeedsFlush = false;
>+          this._updateManifests(false);
>+        }
>+        if (gDSNeedsFlush) {
>+          gDSNeedsFlush = false;
>+          this.datasource.Flush();
>+        }
>+      }
>+      catch (e) {
>+        ERROR("Error flushing caches: " + e);
>+      }
>+    }
Since we shouldn't get into this state in the first place it might be helpful to add a call to ERROR at the start of the try.

>@@ -3909,20 +3976,31 @@ ExtensionManager.prototype = {
>   },
> 
>   /**
>    * Write the Extensions List and the Startup Cache
>    * @param   needsRestart
>    *          true if the application needs to restart again, false otherwise.
>    */
>   _updateManifests: function(needsRestart) {
>-    // Write the Startup Cache (All Items, visible or not)
>-    StartupCache.write();
>-    // Write the Extensions Locations Manifest (Visible, enabled items)
>-    this._updateExtensionsManifest(needsRestart);
>+    // During startup we block flushing until the startup operations are all
>+    // complete to reduce file accesses that can trigger bug 431065
>+    if (gAllowFlush) {
>+      LOG("updateManifests");
nit: logging "updateManifests" is a tad vague. Perhaps ExtensionManager:_updateManifests - updating manifests?

>+      // Write the Startup Cache (All Items, visible or not)
>+      StartupCache.write();
>+      // Write the Extensions Locations Manifest (Visible, enabled items)
>+      this._updateExtensionsManifest();
>+    }
>+    else {
>+      gManifestNeedsFlush = true;
>+    }
>+
>+    // Now refresh the compatibility manifest.
nit: it is an old comment but this doesn't actually refresh the compatibility manifest. It does add the .autoreg file to notify nsAppRunner to refresh the compatibility manifest on the next startup.

>@@ -7543,16 +7616,30 @@ ExtensionsDataSource.prototype = {
>    */
>   setItemProperty: function (id, propertyArc, propertyValue) {
>     var item = getResourceForID(id);
>     this._setProperty(this._inner, item, propertyArc, propertyValue);
>     this.Flush();
>   },
> 
>   /**
>+   * Sets a number of properties on an item.
nit: Sets one or more properties for an item.

>+   * @param   id
>+   *          The GUID of the item
nit: we still have references to GUID from the old days but technically it is no longer a GUID. Please use ID or identifier in new comments.
http://en.wikipedia.org/wiki/Globally_Unique_Identifier

>+   * @param   properties
>+   *          A JS object which maps properties to values.
>+   */
>+  setItemProperties: function (id, properties) {
>+    var item = getResourceForID(id);
>+    for (var key in properties)
>+      this._setProperty(this._inner, item, EM_R(key), properties[key]);
>+    this.Flush();
>+  },
Nice!

>@@ -8705,16 +8794,22 @@ ExtensionsDataSource.prototype = {
> 
>   Init: function(uri) {
>   },
> 
>   Refresh: function(blocking) {
>   },
> 
>   Flush: function() {
>+    // During startup we block flushing until the startup operations are all
>+    // complete to reduce file accesses that can trigger bug 431065
nit: will there be times where we may want to block flushes during normal operations? If so, this comment might be better if it slightly were more generic.

r=me

Comment 9

[Dave Townsend [:mossop]]

Attachment: patch rev 3

(In reply to comment #8)
> >-    // Write the Startup Cache (All Items, visible or not)
> >-    StartupCache.write();
> >-    // Write the Extensions Locations Manifest (Visible, enabled items)
> >-    this._updateExtensionsManifest(needsRestart);
> >+    // During startup we block flushing until the startup operations are all
> >+    // complete to reduce file accesses that can trigger bug 431065
> >+    if (gAllowFlush) {
> >+      LOG("updateManifests");
> nit: logging "updateManifests" is a tad vague. Perhaps
> ExtensionManager:_updateManifests - updating manifests?

Jut removed the log call altogether, it was a bit of code I was testing with that I didn't intend to make the final patch.

> >   Flush: function() {
> >+    // During startup we block flushing until the startup operations are all
> >+    // complete to reduce file accesses that can trigger bug 431065
> nit: will there be times where we may want to block flushes during normal
> operations? If so, this comment might be better if it slightly were more
> generic.

I've updated this. Hopefully though this covers the main cases and once we move to sqlite for the main datasource we won't have to worry about this problem except for the startup cache.

Fixed all other comments, carried over review.

Comment 10

[Dave Townsend [:mossop]]

Landed in changeset 8fda6cca7d24. There isn't really an automated way to test this as there is no behaviour change, other tests should just not fail.

Comment 11

[Dave Townsend [:mossop]]

Comment on attachment 331191 [details] [diff] [review]
patch rev 3

I would like to land this on branch. A fair number of people have been hitting issues with anti-virus tools breaking extension installation which this fixes. Since landing on the trunk I have not heard of any side effects

Comment 12

[Samuel Sidler (old account; do not CC)]

Comment on attachment 331191 [details] [diff] [review]
patch rev 3

Approved for 1.9.0.2. Please land in CVS. a=ss

Comment 13

[Dave Townsend [:mossop]]

Landed on branch

Checking in toolkit/mozapps/extensions/src/nsExtensionManager.js.in;
/cvsroot/mozilla/toolkit/mozapps/extensions/src/nsExtensionManager.js.in,v  <--  nsExtensionManager.js.in
new revision: 1.289; previous revision: 1.288
done