Closed Bug 1179209 Opened 4 years ago Closed 4 years ago

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

Categories

(Toolkit :: Telemetry, defect, P3)

defect
Points:
1

Tracking

()

VERIFIED FIXED
mozilla46
Tracking Status
firefox42 --- affected
firefox46 --- verified

People

(Reporter: gfritzsche, Assigned: robertthyberg, Mentored)

References

(Blocks 1 open bug)

Details

(Whiteboard: [measurement:client][lang=js][good next bug])

Attachments

(1 file, 6 obsolete files)

TelemetryEnvironment.registerChangeListener() is only registered late in startup.
If we hit any environment changes before, we still start the 5min throttling.
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?
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.
Blocks: 1201022
No longer blocks: 1122482
Points: --- → 1
Priority: -- → P3
Whiteboard: [measurement:client]
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
Mentor: alessio.placitelli, gfritzsche
Whiteboard: [measurement:client] → [measurement:client][lang=js][good next bug]
Eduard, would you be interested in taking this one?
Flags: needinfo?(hanue)
Moving the ni due to inactivity.

Robert, would you be interested in taking this one?
Flags: needinfo?(hanue) → needinfo?(robertthyberg)
yeah sure thing
Flags: needinfo?(robertthyberg)
Attached patch bug-1179209 (obsolete) — Splinter Review
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.
Attachment #8688164 - Flags: feedback?(alessio.placitelli)
Assignee: nobody → robertthyberg
Status: NEW → ASSIGNED
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.
Attachment #8688164 - Flags: feedback?(alessio.placitelli)
Attached patch bug-1179209 (obsolete) — Splinter Review
Attachment #8688164 - Attachment is obsolete: true
Attachment #8688862 - Flags: feedback?
Attached patch bug-1179209 (obsolete) — Splinter Review
Attachment #8688862 - Attachment is obsolete: true
Attachment #8688862 - Flags: feedback?
Attachment #8688864 - Flags: feedback?(alessio.placitelli)
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.
Attachment #8688864 - Flags: feedback?(alessio.placitelli)
Robert, given comment 11, are you still interested in working on this?
Flags: needinfo?(robertthyberg)
yeah. I just didnt get around to finishing it before Thanksgiving but Im almost there. Ill finish it next week if that's alright.
Flags: needinfo?(robertthyberg)
Attached patch 1179209 (obsolete) — Splinter Review
having some trouble putting the pieces together. Can you take a look?
Attachment #8688864 - Attachment is obsolete: true
Attachment #8695775 - Flags: feedback?(alessio.placitelli)
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.
Attachment #8695775 - Flags: feedback?(alessio.placitelli) → feedback+
Hi Robert,

are you stuck and/or need any help?
Flags: needinfo?(robertthyberg)
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?
Flags: needinfo?(robertthyberg)
Attached patch 1179209_ (obsolete) — Splinter Review
Attachment #8695775 - Attachment is obsolete: true
Attachment #8697145 - Flags: feedback?(alessio.placitelli)
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."
Attachment #8697145 - Flags: feedback?(alessio.placitelli) → feedback+
(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.
Attached patch attachment.cgi?id=8697145 (obsolete) — Splinter Review
Attachment #8697145 - Attachment is obsolete: true
Attachment #8699419 - Flags: review?(alessio.placitelli)
Comment on attachment 8699419 [details] [diff] [review]
attachment.cgi?id=8697145

Bouncing the review to :gfritzsche
Attachment #8699419 - Flags: review?(gfritzsche)
Attachment #8699419 - Flags: review?(alessio.placitelli)
Attachment #8699419 - Flags: feedback+
Attachment #8699419 - Flags: review?(gfritzsche) → review+
QA Contact: alexandra.lucinet
Flags: qe-verify+
(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?
Flags: needinfo?(robertthyberg)
yeah it was no longer throttling changes when switching add ons
Flags: needinfo?(robertthyberg)
(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?
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 [...]
Flags: needinfo?(robertthyberg)
yes both tests worked as expected
Flags: needinfo?(robertthyberg)
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
Flags: needinfo?(robertthyberg)
Attachment #8699419 - Attachment is obsolete: true
Flags: needinfo?(robertthyberg)
Attachment #8700998 - Flags: review?(alessio.placitelli)
Attachment #8700998 - Attachment is patch: true
Comment on attachment 8700998 [details] [diff] [review]
attachment.cgi?id=8697145

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

Looks good, thanks.
Attachment #8700998 - Flags: review?(alessio.placitelli) → review+
Depends on: 1136634
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
https://hg.mozilla.org/mozilla-central/rev/993fd6b313af
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla46
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.
Status: RESOLVED → VERIFIED
Flags: qe-verify+
You need to log in before you can comment on or make changes to this bug.