1179209 - Don't throttle environment changes until there are any environment-change listeners

Status: VERIFIED FIXED

(Toolkit :: Telemetry, defect, P3)

Description

[Georg Fritzsche [:gfritzsche]]

TelemetryEnvironment.registerChangeListener() is only registered late in startup.
If we hit any environment changes before, we still start the 5min throttling.

Comment 1

[Benjamin Smedberg]

Where does that throttling occur? We need to wait for startup to stabilize (especially for any restartless addons to be enabled) before we start watching for environment changes, right?

Comment 2

[Georg Fritzsche [:gfritzsche]]

The throttling happens in the TelemetryEnvironment - with the lazy init & its early triggering, we catch environment changes very early now and from manual testing throttling may be triggered early in startup.
Yes, we need to wait, either by explicitly enabling the listeners later (probably best) or at least waiting until we have >0 change listeners.

Comment 3

[Alessio Placitelli [:Dexter]]

In order to implement the changes from comment 2:

- Check |_changeListeners| to see if there are 0 registered listeners. This needs to happen before |let now = Policy.now();| and after the shutdown check (see [0]).
- If there are no listeners, we should log this condition using |this._log.trace| and return.

In order to test that everything works as expected both xpcshell and manual QA can help:

- ./mach xpcshell-test toolkit/components/telemetry

and

1) Run Firefox (with the toolkit.telemetry.log.level pref string set to "Trace"
2) Disable, install or enable a restartless addon to trigger an environment change before Telemetry fully initializes (so before 1 minute passes from when Firefox was started)
3) The log log that was added by the patch should be seen in the browser console
4) Wait 1 minute
5) Re-enable or re-disable (depending on what was done in step 2) the addon and check that the first of the next two lines is there, but the second isn't (changes should not be throttled)

Toolkit.Telemetry       TRACE   TelemetryEnvironment::_onEnvironmentChange for addons-changed
Toolkit.Telemetry       TRACE   TelemetryEnvironment::_onEnvironmentChange - throttling changes, now [...]

[0] - https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/TelemetryEnvironment.jsm#1289

Comment 4

[Alessio Placitelli [:Dexter]]

Eduard, would you be interested in taking this one?

Comment 5

[Alessio Placitelli [:Dexter]]

Moving the ni due to inactivity.

Robert, would you be interested in taking this one?

Comment 6

[rthyberg]

yeah sure thing

Comment 7

[rthyberg]

Attachment: bug-1179209

I think I am close. I am not sure if I checked changeListeners right. At least nothing broke with ./mach xpcshell-test toolkit/components/telemetry but I wasnt able to see anything in the browser console. I am not sure if I set my browser up right to see the logs or if my code is just not getting called or both.

Comment 8

[Alessio Placitelli [:Dexter]]

Comment on attachment 8688164 [details] [diff] [review]
bug-1179209

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

Yes, you are very close! I'm honestly not quite sure why test_TelemetryEnvironment.js didn't complain, but I can understand why you didn't see any log line.

Do the suggestions below help?

::: toolkit/components/telemetry/TelemetryEnvironment.jsm
@@ +1285,5 @@
>        this._log.trace("_onEnvironmentChange - Already shut down.");
>        return;
>      }
>  
> +    if (this._changeListeners.length == 0) {

This will not work as the length method is undefined for the Map object.

You should be using |this._changeListeners.size|. See https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Map/size#Using_size

@@ +1286,5 @@
>        return;
>      }
>  
> +    if (this._changeListeners.length == 0) {
> +      this._log.trace;

|this._log.trace| is a function that prints a line to the log with the "trace" level (this means that the log line is not shown unless you enable log output at the trace level!).

You should pass that function a string to print, as done a couple of lines above.

Comment 9

[rthyberg]

Attachment: bug-1179209

Comment 10

[rthyberg]

Attachment: bug-1179209

Comment 11

[Alessio Placitelli [:Dexter]]

I'm afraid we need to take another approach for this one. Instead of what suggested in comment 2, we should do as follows:

- Add a |_delayedInitFinished| boolean flag to TelemetryEnvironment, with the default value set to false, near [0].
- Add a |delayedInit()| function to TelemetryEnvironment, which sets the |_delayedInitFinished| flag to true, after [1].
- Call TelemetrEnvironment.delayedInit from TelemetryController's delayed init, after [3]
- In |_onEnvironmentChange| only throttle if |_delayedInitFinished| is true.

[0] - https://dxr.mozilla.org/mozilla-central/rev/a2f83cbe53ac4009afa4cb2b0b8f549289b23eeb/toolkit/components/telemetry/TelemetryEnvironment.jsm#666
[1] - https://dxr.mozilla.org/mozilla-central/rev/a2f83cbe53ac4009afa4cb2b0b8f549289b23eeb/toolkit/components/telemetry/TelemetryEnvironment.jsm#743
[3] - https://dxr.mozilla.org/mozilla-central/rev/a2f83cbe53ac4009afa4cb2b0b8f549289b23eeb/toolkit/components/telemetry/TelemetryController.jsm#755

Sorry for the detour but, as you correctly saw today, we already have a change listener registered when starting up.

Comment 12

[Alessio Placitelli [:Dexter]]

Robert, given comment 11, are you still interested in working on this?

Comment 13

[rthyberg]

yeah. I just didnt get around to finishing it before Thanksgiving but Im almost there. Ill finish it next week if that's alright.

Comment 14

[rthyberg]

Attachment: 1179209

having some trouble putting the pieces together. Can you take a look?

Comment 15

[Alessio Placitelli [:Dexter]]

Comment on attachment 8695775 [details] [diff] [review]
1179209

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

This looks almost there, you did put all the pieces together ;)

::: toolkit/components/telemetry/TelemetryController.jsm
@@ +753,5 @@
>      this._delayedInitTask = new DeferredTask(function* () {
>        try {
>          // TODO: This should probably happen after all the delayed init here.
>          this._initialized = true;
> +        TelemetryEnvironment.EnvironmentCache.delayedInit();

This should be |TelemetryEnvironment.delayedInit();|. In order for that call to work, we need to export |delayedInit| as well, by adding

delayedInit: function() {
  return getGlobal().delayedInit();
},

After https://dxr.mozilla.org/mozilla-central/rev/a2f83cbe53ac4009afa4cb2b0b8f549289b23eeb/toolkit/components/telemetry/TelemetryEnvironment.jsm#66

::: toolkit/components/telemetry/TelemetryEnvironment.jsm
@@ +663,5 @@
>      LOGGER_NAME, "TelemetryEnvironment::");
>    this._log.trace("constructor");
>  
>    this._shutdown = false;
> +  this._delayedInitFinished = false;

Please add a blank line after this line.

@@ +741,5 @@
>      }
>      return Promise.resolve(this.currentEnvironment);
>    },
>  
> +  delayedInit: function() {

Please add a comment for this function.

Comment 16

[Alessio Placitelli [:Dexter]]

Hi Robert,

are you stuck and/or need any help?

Comment 17

[rthyberg]

Yeah I do. Couple things. I got a new computer and I dont remeber how to make "Trace" show up in the terminal. Also some of the tests are not working from a fresh compile of firefox (no patchs applied). I made the changes you reccommened by due to teh issues I havnt been able to test it. Ill post the patch for feedback and then you can help me address these issues?

Comment 18

[rthyberg]

Attachment: 1179209_

Comment 19

[Alessio Placitelli [:Dexter]]

Comment on attachment 8697145 [details] [diff] [review]
1179209_

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

Thank you Robert. This looks good to me, assuming that it works as expected.

::: toolkit/components/telemetry/TelemetryEnvironment.jsm
@@ +747,5 @@
>      return Promise.resolve(this.currentEnvironment);
>    },
>  
>    /**
> +   * Flag the delayedInitTask from TelemetryController has finished.

"This gets called when the delayed init completes."

Comment 20

[Alessio Placitelli [:Dexter]]

(In reply to rthyberg from comment #17)
> Yeah I do. Couple things. I got a new computer and I dont remeber how to
> make "Trace" show up in the terminal. Also some of the tests are not working
> from a fresh compile of firefox (no patchs applied). I made the changes you
> reccommened by due to teh issues I havnt been able to test it. Ill post the
> patch for feedback and then you can help me address these issues?

To enable dumping the log to the terminal, you should set the "toolkit.telemetry.log.dump" preference to |true|.

Which test is failing? Are you on the most recent mozilla-central?

Also, in addition to the tests in comment 3, since the eslint support has landed, you should also make sure your patch passes the basic linting we have in place. You can do this by running:

./mach eslint toolkit/components/telemetry

There should not be any issue reported.

Comment 21

[rthyberg]

Attachment: attachment.cgi?id=8697145

Comment 22

[Alessio Placitelli [:Dexter]]

Comment on attachment 8699419 [details] [diff] [review]
attachment.cgi?id=8697145

Bouncing the review to :gfritzsche

Comment 23

[Alessio Placitelli [:Dexter]]

(In reply to rthyberg from comment #21)
> Created attachment 8699419 [details] [diff] [review]
> attachment.cgi?id=8697145

Robert, did you make sure this works as explained in comment 3?

Comment 24

[rthyberg]

yeah it was no longer throttling changes when switching add ons

Comment 25

[Alessio Placitelli [:Dexter]]

(In reply to rthyberg from comment #24)
> yeah it was no longer throttling changes when switching add ons

Can you confirm that throttling still happens after 60s, when disabling and then enabling an addon?

Comment 26

[Alessio Placitelli [:Dexter]]

I mean, other than the tests in comment 3, also:

1) Run Firefox (with the toolkit.telemetry.log.level pref string set to "Trace"
2) Disable, install or enable a restartless addon to trigger an environment change before Telemetry fully initializes (so before 1 minute passes from when Firefox was started)
3) The log log that was added by the patch should be seen in the browser console
4) Wait 1 minute
5) Re-enable or re-disable (depending on what was done in step 2) the addon and check that the first of the next two lines is there, but the second isn't (changes should not be throttled)

Toolkit.Telemetry       TRACE   TelemetryEnvironment::_onEnvironmentChange for addons-changed
Toolkit.Telemetry       TRACE   TelemetryEnvironment::_onEnvironmentChange - throttling changes, now [...]

6 (the new step) ) Re-enable or re-disable (depending on the previous step) the addon and check that BOTH the following lines are in the log:

Toolkit.Telemetry       TRACE   TelemetryEnvironment::_onEnvironmentChange for addons-changed
Toolkit.Telemetry       TRACE   TelemetryEnvironment::_onEnvironmentChange - throttling changes, now [...]

Comment 27

[rthyberg]

yes both tests worked as expected

Comment 28

[Alessio Placitelli [:Dexter]]

There's one last thing that I found while test-driving this patch: we're still throttling if we make an environment change right after Telemetry inits (testing step 5 from comment 26 is failing). We should not throttle the first change there, only the next ones.

The fix is trivial: we should protect |this._lastEnvironmentChangeDate = now;| [0] by checking |this._delayedInitFinished|.

We should also make sure tests are aware of this, so another change is needed in [1]: simply add |TelemetryEnvironment.delayedInit();| after |spoofProfileReset|.

The testing instructions from comment 26 still hold.

[0] - https://dxr.mozilla.org/mozilla-central/rev/0711218a018d912036f7d3be2ae2649e213cfb85/toolkit/components/telemetry/TelemetryEnvironment.jsm#1316
[1] - https://dxr.mozilla.org/mozilla-central/rev/0711218a018d912036f7d3be2ae2649e213cfb85/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js#667

Comment 29

[rthyberg]

Attachment: attachment.cgi?id=8697145

Comment 30

[Alessio Placitelli [:Dexter]]

Comment on attachment 8700998 [details] [diff] [review]
attachment.cgi?id=8697145

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

Looks good, thanks.

Comment 31

[Alessio Placitelli [:Dexter]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=03dc94ee5cb1

Comment 32

[Alessio Placitelli [:Dexter]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0bb417cc198d

Comment 33

[Alessio Placitelli [:Dexter]]

https://hg.mozilla.org/integration/fx-team/rev/993fd6b313af4b40f4c09f9ab8fa3ea60dac935c
Bug 1179209 - Don't throttle environment changes until there are any environment-change listeners. r=dexter

Comment 34

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/993fd6b313af

Comment 35

[Ada [:adalucinet]]

Verified fixed with 46.0b8 (Build ID: 20160404120533), under Windows 7 64-bit, Mac OS X 10.11.1 and Ubuntu 14.04 32-bit - no throttling before Telemetry inits and none at the first environment change after Telemetry inits.