988301 - Avoid main-thread IO in Sync code

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Roberto Agostino Vitillo (:rvitillo)]

The following files are main-thread IO offenders and appear in about 5-10% of Telemetry's submissions.

{profile}\weave\changes
{profile}\weave\failed
{profile}\weave\toFetch
{profile}\weave\changes\forms.json
{profile}\weave\changes\passwords.json
{profile}\weave\changes\bookmarks.json
{profile}\weave\changes\history.json
{profile}\weave\changes\clients.json
{profile}\weave\changes\addons.json
{profile}\weave\toFetch\tabs.json
{profile}\weave\toFetch\prefs.json
{profile}\weave\toFetch\history.json
{profile}\weave\toFetch\passwords.json
{profile}\weave\toFetch\forms.json
{profile}\weave\toFetch\bookmarks.json
{profile}\weave\toFetch\clients.json
{profile}\weave\failed\passwords.json
{profile}\weave\failed\tabs.json
{profile}\weave\failed\clients.json
{profile}\weave\failed\history.json
{profile}\weave\failed\addons.json
{profile}\weave\failed\bookmarks.json
{profile}\weave\failed\prefs.json
{profile}\weave\toFetch\addons.json
{profile}\weave\failed\forms.json
{profile}\weave\addonsreconciler.json
{profile}\weave\changes\adblockplus.json
{profile}\weave\failed\adblockplus.json
{profile}\weave\toFetch\adblockplus.json

Comment 1

[Richard Newman [:rnewman]]

Yeah, Sync does everything bad that you wish you could go back to 2008 and tell people not to do: main-thread IO, spinning the event loop, synchronous programming style.

Fixing this without introducing lots more event loop spinning is a big chunk of work, and I don't see anything that's changed in the org that will prioritize a rewrite. Fingers crossed.

Comment 2

[Gregory Szorc [:gps]]

While properly fixing Sync would involve a nearly complete rewrite, I think the I/O issues could be addressed.

It seems to me the culprit is services/sync/modules/util.js:{jsonLoad, jsonSave}. Those functions already use callbacks. We should be able to drop in OS.File to make this problem go away.

Comment 3

[Marco Castelluccio [:marco]]

(In reply to Gregory Szorc [:gps] from comment #2)
> While properly fixing Sync would involve a nearly complete rewrite, I think
> the I/O issues could be addressed.
> 
> It seems to me the culprit is services/sync/modules/util.js:{jsonLoad,
> jsonSave}. Those functions already use callbacks. We should be able to drop
> in OS.File to make this problem go away.

Aren't NetUtil.asyncFetch and NetUtil.asyncCopy already doing IO off the main thread?

Comment 4

[Richard Newman [:rnewman]]

(In reply to Gregory Szorc [:gps] from comment #2)

> It seems to me the culprit is services/sync/modules/util.js:{jsonLoad,
> jsonSave}. Those functions already use callbacks. We should be able to drop
> in OS.File to make this problem go away.

Indeed, we have services/common/util.js:readJSON,writeJSON that use OS.File and return promises.

Comment 5

[Marco Bonardo [:mak]]

(In reply to Marco Castelluccio [:marco] from comment #3)
> Aren't NetUtil.asyncFetch and NetUtil.asyncCopy already doing IO off the
> main thread?

I think bug 928340 and bug 801599 are good answers to this (to sum up, they are not so async as the name states)

Comment 6

[Marco Castelluccio [:marco]]

I'll take this.

Comment 7

[Marco Castelluccio [:marco]]

I'm mostly done. There are still a couple of failing tests, I think it is a timing problem.

For example, in test_syncengine_sync.js, |test_processIncoming_previousFailed| fails only if I also run the previous |test_processIncoming_notify_count| test.
In  |test_processIncoming_previousFailed| the failure is in the initial environment checks. So, it looks like the previous test left the environment in an unclean state (indeed if I make jsonSave a no-op, the test passes).

Comment 8

[Marco Castelluccio [:marco]]

Attachment: Patch

Actually the problem was that in services/sync/modules/util.js we're importing FileUtils.jsm and NetUtil.jsm and re-exporting them to users of the module. I did remove the imports because they weren't necessary in the util.js module and I thought that users of the module would break in a clear way so that I could fix them one by one.
Instead, there wasn't any error message.

Comment 9

[Marco Castelluccio [:marco]]

Comment on attachment 8397466 [details] [diff] [review]
Patch

There are still a couple of failures.
test_tracker_addChanged.js - Timeout on try, OK locally.
test_syncengine_sync.js - Fails in a seemingly random way (I think there's a race condition between the tests contained in the file).

Comment 10

[Marco Castelluccio [:marco]]

I don't have time at the moment to fix those issues, I may re-take this in the future if no one else steps in.

Comment 11

[Marco Castelluccio [:marco]]

Attachment: Patch

This is the latest version of the patch.

Comment 12

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v3

Comment 13

[Roberto Agostino Vitillo (:rvitillo)]

(In reply to Roberto Agostino Vitillo (:rvitillo) from comment #12)
> Created attachment 8399260 [details] [diff] [review]
> Avoid main-thread IO in Sync code, v3

https://tbpl.mozilla.org/?tree=Try&rev=b15402eee237

Comment 14

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

Comment on attachment 8399260 [details] [diff] [review]
Avoid main-thread IO in Sync code, v3

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

::: services/sync/modules/policies.js
@@ +13,5 @@
>  Cu.import("resource://services-sync/constants.js");
>  Cu.import("resource://services-sync/engines.js");
>  Cu.import("resource://services-sync/util.js");
> +Cu.import("resource://gre/modules/FileUtils.jsm");
> +Cu.import("resource://gre/modules/NetUtil.jsm");

Do you need this here?

::: services/sync/modules/util.js
@@ +344,5 @@
>      if (that._log) {
>        that._log.trace("Loading json from disk: " + filePath);
>      }
>  
> +    if (!(yield OS.File.exists(path))) {

Actually, that's a counter-pattern.
The right way to do this is to
try {
  yield OS.File.read() // Or other reading op
} catch (ex if ex instanceof OS.File.Error
            && ex.becauseNoSuchFile) {
  // Handle non-existent file
}

@@ +381,5 @@
>     *        constant on error or null if no error was encountered (and
>     *        the file saved successfully).
>     */
> +  jsonSave: Task.async(function*(filePath, that, obj, callback) {
> +    let dir = OS.Path.join(OS.Constants.Path.profileDir, "weave");

Unless you intend to uplift, you can now simply write
 yield OS.File.makeDir(dir, {from: OS.Constants.Path.profileDir})l
this should also be faster than the code you have below.

::: services/sync/tests/unit/test_errorhandler.js
@@ +9,5 @@
>  Cu.import("resource://services-sync/service.js");
>  Cu.import("resource://services-sync/status.js");
>  Cu.import("resource://services-sync/util.js");
>  Cu.import("resource://testing-common/services/sync/utils.js");
> +Cu.import("resource://gre/modules/FileUtils.jsm");

Do you need this here?

Comment 15

[Marco Castelluccio [:marco]]

(In reply to Roberto Agostino Vitillo (:rvitillo) from comment #12)
> Created attachment 8399260 [details] [diff] [review]
> Avoid main-thread IO in Sync code, v3

Right, I was modifying everything to use promises, but this is safer.

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #14)
> ::: services/sync/modules/policies.js
> @@ +13,5 @@
> >  Cu.import("resource://services-sync/constants.js");
> >  Cu.import("resource://services-sync/engines.js");
> >  Cu.import("resource://services-sync/util.js");
> > +Cu.import("resource://gre/modules/FileUtils.jsm");
> > +Cu.import("resource://gre/modules/NetUtil.jsm");
> 
> Do you need this here?

The FileUtils.jsm and NetUtil.jsm modules were imported and re-exported by util.js. So if we stop doing this, we need to import them directly when needed.

> ::: services/sync/modules/util.js
> @@ +344,5 @@
> >      if (that._log) {
> >        that._log.trace("Loading json from disk: " + filePath);
> >      }
> >  
> > +    if (!(yield OS.File.exists(path))) {
> 
> Actually, that's a counter-pattern.
> The right way to do this is to
> try {
>   yield OS.File.read() // Or other reading op
> } catch (ex if ex instanceof OS.File.Error
>             && ex.becauseNoSuchFile) {
>   // Handle non-existent file
> }

The old code called |callback.call(that)| for every file-related error. So, to keep the old behavior, you could just do:
try {
  yield read
} catch (e if e instanceof OS.File.Error) {
  callback.call(that);
} ...

Comment 16

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v4

Comment 17

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

Comment on attachment 8399458 [details] [diff] [review]
Avoid main-thread IO in Sync code, v4

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

::: services/sync/modules/util.js
@@ +351,5 @@
> +      json = yield CommonUtils.readJSON(path)
> +    } catch (e) {
> +      if (that._log) {
> +        that._log.debug("Failed to load json: " +
> +                        CommonUtils.exceptionStr(e));

It is my understanding that we don't want to report an error if the file just doesn't exist.

@@ +381,5 @@
> +    let error = null;
> +
> +    try {
> +      yield OS.File.makeDir(dir, { ignoreExisting: true,
> +                                  from: OS.Constants.Path.profileDir })

Nit: I'd intend so that |from| is below |ignoreExisting|.

@@ -400,5 @@
> -    let json = typeof obj == "function" ? obj.call(that) : obj;
> -    let out = JSON.stringify(json);
> -
> -    let fos = FileUtils.openSafeFileOutputStream(file);
> -    let is = this._utf8Converter.convertToInputStream(out);

Do you still need this._utf8Converter?

Comment 18

[Roberto Agostino Vitillo (:rvitillo)]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #17)
> @@ -400,5 @@
> > -    let json = typeof obj == "function" ? obj.call(that) : obj;
> > -    let out = JSON.stringify(json);
> > -
> > -    let fos = FileUtils.openSafeFileOutputStream(file);
> > -    let is = this._utf8Converter.convertToInputStream(out);
> 
> Do you still need this._utf8Converter?

Yes, it's needed by encodeUTF8.

Comment 19

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v5

Comment 20

[Marco Castelluccio [:marco]]

Comment on attachment 8399494 [details] [diff] [review]
Avoid main-thread IO in Sync code, v5

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

::: services/sync/modules/util.js
@@ +353,5 @@
> +    } catch (e) {
> +      if (that._log) {
> +        that._log.debug("Failed to load json: " +
> +                        CommonUtils.exceptionStr(e));
> +      }

If you want to keep the old behavior here (no logging for IO errors):
try {
  json = yield CommonUtils.readJSON(path);
} catch (e if e instanceof OS.File.Error) {
} catch (e) {
  ...
}

Note that this is exactly equivalent to what you're doing, because readJSON will never fail with e.becauseExists.

Otherwise, if you want to log all errors:
try {
  json = yield CommonUtils.readJSON(path);
} catch (e) {
  ...
}

Comment 21

[Roberto Agostino Vitillo (:rvitillo)]

(In reply to Marco Castelluccio [:marco] from comment #20)
> Comment on attachment 8399494 [details] [diff] [review]
> Avoid main-thread IO in Sync code, v5
> 
> Review of attachment 8399494 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: services/sync/modules/util.js
> @@ +353,5 @@
> > +    } catch (e) {
> > +      if (that._log) {
> > +        that._log.debug("Failed to load json: " +
> > +                        CommonUtils.exceptionStr(e));
> > +      }
> 
> If you want to keep the old behavior here (no logging for IO errors):
> try {
>   json = yield CommonUtils.readJSON(path);
> } catch (e if e instanceof OS.File.Error) {
> } catch (e) {
>   ...
> }

My bad, what I really had in mind was e.becauseNoSuchFile...

Comment 22

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v6

Comment 23

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

Comment on attachment 8399530 [details] [diff] [review]
Avoid main-thread IO in Sync code, v6

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

r=me, with a few changes below.
As I don't have review rights on that directory, you will need review from someone who has.

::: services/sync/modules/util.js
@@ +348,5 @@
> +    let json;
> +
> +    try {
> +      json = yield CommonUtils.readJSON(path)
> +    } catch (e if e instanceof OS.File.Error) {

This actually doesn't make sense – not your fault, it didn't make sense before either.

You whould ignore only |if e instanceof OS.File.Error && e.becauseNoSuchFile|. Other errors should be logged. Also, please add a comment
 // Ignore non-existent files
to the corresponding branch.

@@ +377,5 @@
>     *        the file saved successfully).
>     */
> +  jsonSave: Task.async(function*(filePath, that, obj, callback) {
> +    let path = OS.Path.join(OS.Constants.Path.profileDir, "weave", filePath + ".json");
> +    let dir = OS.Path.dirname(path);

Can you change the order?
let dir = OS.Path.join(..., "weave")
let path = OS.Path.join(dir, filePath + ".json")

@@ +381,5 @@
> +    let dir = OS.Path.dirname(path);
> +    let error = null;
> +
> +    try {
> +      yield OS.File.makeDir(dir, { ignoreExisting: true,

You don't need ignoreExisting anymore. It's now default.

@@ +382,5 @@
> +    let error = null;
> +
> +    try {
> +      yield OS.File.makeDir(dir, { ignoreExisting: true,
> +                                   from: OS.Constants.Path.profileDir })

Nit: semi-column.

Comment 24

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

By the way, perhaps we need to plug stuff into AsyncShutdown. Or is it ok if we are killed during an async write?

Comment 25

[Gregory Szorc [:gps]]

Plugging Sync into AsyncShutdown should probably be done. However, I think the failure window already exists and doesn't change with this patch (please correct me if my assumptions about how OS.File handles shutdown are accurate) and thus we should not worry about it here.

Comment 26

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v7

Comment 27

[Richard Newman [:rnewman]]

Comment on attachment 8399913 [details] [diff] [review]
Avoid main-thread IO in Sync code, v7

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

Looks fine to me, assuming tests pass.

::: services/sync/modules/util.js
@@ +347,5 @@
>  
> +    let json;
> +
> +    try {
> +      json = yield CommonUtils.readJSON(path)

Trailing ;

@@ +349,5 @@
> +
> +    try {
> +      json = yield CommonUtils.readJSON(path)
> +    } catch (e if e instanceof OS.File.Error && e.becauseNoSuchFile) {
> +      // Ignore non-existent files

Trailing .

Comment 28

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v8

https://tbpl.mozilla.org/?tree=Try&rev=371829dc3d2e

Comment 29

[Roberto Agostino Vitillo (:rvitillo)]

After the latest changes the following xpcshell test timeouts on all Windows builds:

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\sync\tests\unit\test_tracker_addChanged.js | test failed (with xpcshell return code: 15)

Comment 30

[Marco Castelluccio [:marco]]

The filePath argument is a path in Unix format, maybe this is causing troubles for OS.Path.join on Windows?

Comment 31

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

Right. We expect paths to use native format. You should create filePath using OS.Path.join().

Comment 32

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v9

https://tbpl.mozilla.org/?tree=Try&rev=039897f4c5ed

Comment 33

[Roberto Agostino Vitillo (:rvitillo)]

Attachment: Avoid main-thread IO in Sync code, v9

Comment 34

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/da1c426d69fa

Comment 35

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/da1c426d69fa