828201 - [OS.File] Replace DEBUG constant by a preference

Status: RESOLVED FIXED

(Toolkit Graveyard :: OS.File, defect)

Description

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

At the moment, logging in OS.File is conditioned by a constant DEBUG. We should replace this constant by a preference (for instance "toolkit.osfile.log").

This involves the following changes:
- osfile_async_worker.js should accept a message that sets DEBUG to |true| or |false| (for instance "LOG", with a boolean argument), the default being |false|;
- osfile_async_front.jsm should set its own DEBUG from the preference, the default being |false|.

Comment 1

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: DEBUG switched from constant to preference.

Hi David,

I have a sketch patch that removes the constant and uses the preference instead (your suggestions would be great!). I was wondering if you might have any pointers as to how to test the logging that depends on the preference. As far as I can tell, LOG is either deferred to console.log or dump (osfile_shared_allthreads.jsm). I tried testing it by attaching a Services.console.registerListener however console service does not seem to catch the logged messages.

Thanks.

Comment 2

[Josh Matthews [:jdm]]

dump statements go to the terminal window, if you haven't looked there yet.

Comment 3

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

Good question. I have no idea how we could test the output of LOG. However, given that this is purely debugging code, I am willing to accept a patch without a unit test ensuring that the logs are effectively displayed. Of course, I'd still like unit tests that nothing breaks by changing the preference, but I'm willing to take your word on whether the output is right.

Comment 4

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

Actually, Ms2ger suggested a nice hack.
You should be able to test that something isn't output by attempting to output  "\nTEST-UNEXPECTED-FAIL". That only covers half of the problem, but it's a start.

Comment 5

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

Comment on attachment 702146 [details] [diff] [review]
DEBUG switched from constant to preference.

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

Looks good. You will need to handle the asynchronous version, too.

::: toolkit/components/osfile/osfile_shared_allthreads.jsm
@@ +48,5 @@
> +        * appropriately.
> +        */
> +       Services.prefs.addObserver(PREF_OSFILE_LOG,
> +         function (aSubject, aTopic, aData) {
> +           exports.OS.Shared.DEBUG = Services.prefs.getBoolPref(PREF_OSFILE_LOG);

We should probably protect this in a try {} catch {} block and default to false in case of error.

Comment 6

[Yura Zenevich [:yzen] (please use "needinfo")]

(In reply to David Rajchenbach Teller [:Yoric] from comment #4)
> Actually, Ms2ger suggested a nice hack.
> You should be able to test that something isn't output by attempting to
> output  "\nTEST-UNEXPECTED-FAIL". That only covers half of the problem, but
> it's a start.

I think it might be still a little problematic since conditional printing of logs is not yet available (re #828204). At the moment LOG and DEBUG are separate which means DEBUG does not really affect LOG outside of debugging steps within OS.File functions such as:

if (DEBUG) {LOG...}

Comment 7

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Updated Patch: DEBUG switched from constant to preference.

Updated preference retrieval to be inside of the try/catch block.

David, you mentioned I would need to handle the asynchronous version as well, I was wondering if you might have some more detail or an example. My assumption was that [exports.]OS.Shared... is where all osfile components find LOG and DEBUG already.

I will spend some more time trying to come up with a testing strategy for this as well :)

Comment 8

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

(In reply to Yura Zenevich [:yzen] from comment #6)
> (In reply to David Rajchenbach Teller [:Yoric] from comment #4)
> > Actually, Ms2ger suggested a nice hack.
> > You should be able to test that something isn't output by attempting to
> > output  "\nTEST-UNEXPECTED-FAIL". That only covers half of the problem, but
> > it's a start.
> 
> I think it might be still a little problematic since conditional printing of
> logs is not yet available (re #828204). At the moment LOG and DEBUG are
> separate which means DEBUG does not really affect LOG outside of debugging
> steps within OS.File functions such as:
> 
> if (DEBUG) {LOG...}

Yeah, let's forget about that hack.

Comment 9

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

(In reply to Yura Zenevich [:yzen] from comment #7)
> Created attachment 702674 [details] [diff] [review]
> Updated Patch: DEBUG switched from constant to preference.
> 
> Updated preference retrieval to be inside of the try/catch block.
> 
> David, you mentioned I would need to handle the asynchronous version as
> well, I was wondering if you might have some more detail or an example. My
> assumption was that [exports.]OS.Shared... is where all osfile components
> find LOG and DEBUG already.

Yes, but you can access preferences only from the main thread. So currently, for the asynchronous version, the worker-side DEBUG is always false. You need to add a way to send DEBUG from the controller to the worker.

> I will spend some more time trying to come up with a testing strategy for
> this as well :)

Have fun :)

Comment 10

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

Comment on attachment 702674 [details] [diff] [review]
Updated Patch: DEBUG switched from constant to preference.

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

::: toolkit/components/osfile/osfile_async_front.jsm
@@ +26,5 @@
>  let LOG = OS.Shared.LOG.bind(OS.Shared, "Controller");
>  let isTypedArray = OS.Shared.isTypedArray;
>  
> +// A flag used to control debugging messages.
> +let DEBUG = OS.Shared.DEBUG;

Actually, that's probably not what we want. Since we observe the changes to the preference and update OS.Shared.DEBUG accordingly, we should also update DEBUG accordingly.

So, I guess that DEBUG should be a getter.

::: toolkit/components/osfile/osfile_async_worker.js
@@ +15,5 @@
>     try {
>       importScripts("resource://gre/modules/osfile.jsm");
>  
> +     // A flag used to control debugging messages.
> +     let DEBUG = exports.OS.Shared.DEBUG;

Here, you also need to mirror the changes to OS.Shared.DEBUG. This will require sending some message from osfile_async_front.jsm.

::: toolkit/components/osfile/osfile_shared_allthreads.jsm
@@ +46,5 @@
> +           // In case there was an error reading a preference and the DEBUG
> +           // was not set previously, set it to false.
> +           if (typeof pref === "undefined") {
> +             pref = false;
> +           }

If the error is anything else, let's report the error.

Comment 11

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Updated Patch: DEBUG switched from constant to preference.

Hi David, I updated the patch and added really basic test for preference set/unset. I am currently using watch to observe changes of OS.Shared.DEBUG from within osfile_async_front.jsm. I was thinking another way of listening for this pref change could be updating the setter for DEBUG property, but perhaps you have a better idea. Hopefully 828204 will eliminate the issue entirely.

Comment 12

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

Comment on attachment 703783 [details] [diff] [review]
Updated Patch: DEBUG switched from constant to preference.

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

Looks good. I don't think we're quite done, but we're getting close.

::: toolkit/components/osfile/osfile_async_front.jsm
@@ +111,5 @@
> +// Watch changes to DEBUG and update worker's DEBUG accordingly.
> +OS.Shared.watch("DEBUG", function (id, oldVal, newVal) {
> +  Scheduler.post("LOG", [newVal]);
> +  return newVal;
> +});

Nice one, but I would rather use a getter/setter pair, as |watch| is near-deprecated (see https://developer.mozilla.org/en-US/docs/JavaScript/Reference/Global_Objects/Object/watch#Description )

::: toolkit/components/osfile/osfile_async_worker.js
@@ +198,5 @@
>        * back the results.
>        */
>       let Agent = {
> +       // Update DEBUG flag message from controller.
> +       LOG: function LOG (aDEBUG) {

Maybe |SET_DEBUG| would be clearer than |LOG|.

@@ +200,5 @@
>       let Agent = {
> +       // Update DEBUG flag message from controller.
> +       LOG: function LOG (aDEBUG) {
> +         DEBUG = aDEBUG;
> +         return "Logging is " + (DEBUG ? "enabled." : "disabled.");

I don't think that you use that return value, do you?

::: toolkit/components/osfile/osfile_shared_allthreads.jsm
@@ +37,5 @@
> +
> +       Cu.import("resource://gre/modules/Services.jsm");
> +
> +       const PREF_OSFILE_LOG = "toolkit.osfile.log";
> +

Function |readDebugPref| is perhaps a little over-generic for what it does. That's not really an issue, but could you add a little docstring to describe that function?

::: toolkit/components/osfile/tests/mochi/main_test_osfile_async.js
@@ +642,5 @@
> +    }
> +    testSetDebugPref(true);
> +    testSetDebugPref(false);
> +  });
> +});
\ No newline at end of file

Nice test. If you want to test whether the off-main-thread value of OS.Shared.DEBUG works nicely, you could also implement a |GET_LOG| call that just asynchronously returns the value of OS.Shared.DEBUG.

Comment 13

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: DEBUG switched from constant to preference. Addressed latest comments.

Comment 14

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

Comment on attachment 703977 [details] [diff] [review]
DEBUG switched from constant to preference. Addressed latest comments.

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

Looks good. r=me with the following trivial changes.
Don't forget to put your name on the patch :)

::: toolkit/components/osfile/osfile_shared_allthreads.jsm
@@ +45,5 @@
> +        *
> +        * @param bool oldPref
> +        *        An optional value that the DEBUG flag was set to previously.
> +        */
> +       let readDebugPref = function (oldPref) {

Nit: please name the function.

@@ +55,5 @@
> +             // In case of an error when reading a pref keep it as is.
> +             pref = oldPref;
> +           } else {
> +             // Report an unexpected error.
> +             Cu.reportError(x);

Actually, that branch can never happen, can it?

@@ +72,5 @@
> +        * Listen to PREF_OSFILE_LOG changes and update the shared DEBUG flag
> +        * appropriately.
> +        */
> +       Services.prefs.addObserver(PREF_OSFILE_LOG,
> +         function (aSubject, aTopic, aData) {

Nit: please name the function.

Comment 15

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: DEBUG switched from constant to preference.

Includes latest trivial changes.

Comment 16

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

Can we mark this bug checkin-needed?

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d8d79ba17527

Comment 18

[Ryan VanderMeulen [:RyanVM]]

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

Comment 19

[Kartikaya Gupta (email:[e-mail])]

This patch may have caused a regression in memory usage on Fennec. Was an increase in memory usage intentional? See bug 837131.

Comment 20

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

I find this very unlikely. Do we have elements to incriminate this patch rather than another one in the cset?

Comment 21

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

Ah, it seems that we do. Investigating.

Comment 22

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

Could it be that we now import Services.jsm?
@kats, any suggestion as to how we could experiment this?

Comment 23

[Kartikaya Gupta (email:[e-mail])]

(In reply to David Rajchenbach Teller [:Yoric] from comment #22)
> Could it be that we now import Services.jsm?
> @kats, any suggestion as to how we could experiment this?

It could be. Reproducing this should be as simple as loading a build onto an android device (probably want to uninstall previous builds first to start with a fresh profile), waiting 30 seconds (possibly less) and then going to about:memory. You can also use "adb shell am broadcast -a org.mozilla.gecko.MEMORY_DUMP" instead of going about:memory; the memory dump will be written to a file and the filename will be output to logcat. The "resident" and "explicit" memory values both jumped up significantly.

That being said, if you don't have a quick fix in mind I'd prefer this patch got backed out while the investigation happens.

Comment 24

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

If this import is the culprit, it could be fixed in ~10 chars. However, if you believe we should back out for the moment, that shouldn't be a problem. The only patch dependent on this one hasn't landed yet.

Comment 25

[Kartikaya Gupta (email:[e-mail])]

If it's not 100% sure what the problem is (which seems to be the case here) then I think it's safer to back out and then re-land once we have tested the new patch and made sure it doesn't have the regression.

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/8728de36d4a8

Comment 26

[Yura Zenevich [:yzen] (please use "needinfo")]

Should I then go ahead and try to switch from importing all of Services to just preferences observer? Is Bug 837131 resolvable given that Bug 836429 was backed out as well ?

Comment 27

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

(In reply to Yura Zenevich [:yzen] from comment #26)
> Should I then go ahead and try to switch from importing all of Services to
> just preferences observer? Is Bug 837131 resolvable given that Bug 836429
> was backed out as well ?

Before importing just the preferences observer, I would test importing explicitly to scope |this|, rather than the default scope.

For Bug 836429, transmitting needinfo? to kats

Comment 28

[Kartikaya Gupta (email:[e-mail])]

(In reply to Yura Zenevich [:yzen] from comment #26)
> Is Bug 837131 resolvable given that Bug 836429
> was backed out as well ?

I have resolved both bug 836429 and bug 837131 with the backout of this bug, now that I have the data to confirm that the regression was undone by the backout.

Comment 29

[Yura Zenevich [:yzen] (please use "needinfo")]

Turns out the absence I mentioned in the channel today was my mistake, I had a typo in the file and that's why the workers allocation was absent from about:memory. Here, however are my other observations:

* When building from the default branch, I get 2.77-2.78MB allocation for osfile_async_worker.

* When building from the 828201 branch that contains changes from the latest patch + addition to this as a scope argument, I get the same 2.78MB allocation for osfile_async_worker.

* When building from the 828201 branch and instead of loading Services I just load nsIPrefService, I still get the same 2.78MB.

Comment 30

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

By "default branch", do you mean with or without your patch?

Comment 31

[Yura Zenevich [:yzen] (please use "needinfo")]

Yes, default meaning without my patch.

Comment 32

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

I'd go for |Services| and |this|, as it is more readable. Kats, can you confirm that Yzen's observation in comment 29 should be sufficient to ensure that the regression is fixed?

Comment 33

[Kartikaya Gupta (email:[e-mail])]

Want to make sure I understand:

- "default branch" refers to mozilla-central as it exists right now (i.e. with the original patch landed and backed out)
- "828201 branch" refers to some private branch you have where you're working on a new version of the patch with the described changes

Did you also verify that the allocation for osfile_async_worker goes up when you test with just the original patch? If so, then yes, it sounds like the regression is fixed. My concern is that if you test with the original patch and still get the same 2.78MB allocation, then it may be that the allocation shows up somewhere else from where you're looking and so your new patch may also not fix the problem.

Does that make sense?

Comment 34

[Yura Zenevich [:yzen] (please use "needinfo")]

After some investigation, it looks like this line causes the memory allocation to increase.

Within the osfile, promise worker is initialized lazily (see lines 80-145 of _PromiseWorker.jsm) which means that until the message is posted, ChromeWorker is not created.

As part of this patch, SET_DEBUG is called automatically on osfile_async_front.jsm load in order to update worker's DEBUG flag. This is done through posting a message with PromiseWorker which leads to an early creation of the ChromeWorker.

I believe this is the reason for the memory issue. David, would you have a suggestion as how to address this? I was thinking it might be sensible to only SET_DEBUG on osfile_async_front.jsm load iff the DEBUG is true. Let me know what you think.

Comment 35

[Yura Zenevich [:yzen] (please use "needinfo")]

Sorry, the line in question is:

Line 112 of osfile_async_front.jsm (from the latest patch).

Comment 36

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

(In reply to Yura Zenevich [:yzen] from comment #34)
> I believe this is the reason for the memory issue. David, would you have a
> suggestion as how to address this? I was thinking it might be sensible to
> only SET_DEBUG on osfile_async_front.jsm load iff the DEBUG is true. Let me
> know what you think.

That makes lots of sense.

Comment 37

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Update patch with addressed memory issue.

Comment 38

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: This is the diff of memory dump on fennec armv6 between master and master + this patch.

Comment 39

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Properly working locale with the latest patch.

Comment 40

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: Properly working locale with the latest patch (2).

Comment 41

[Yura Zenevich [:yzen] (please use "needinfo")]

Blinky helped me with testing the build that contains the latest patch (https://www.dropbox.com/sh/1aynaogqx5pq068/TypcB3akKH) and neither of us could reproduce Bug 837419.

Comment 42

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b7ef5223023a

Comment 43

[Ed Morley [:emorley]]

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