1482466 - activeTicks simpleMeasurement doesn't always match browser.engagement.active_ticks scalar

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P1)

Description

[Tim Smith (inactive) 👨‍🔬 [:tdsmith]]

Looking at values in pings, the activeTicks simple measurement (payload.simpleMeasurements.activeTicks) often has a higher value than the nominally equivalent scalar (payload.processes.parent.scalars."browser.engagement.active_ticks"). 

I did a bit of investigation here: https://dbc-caf9527b-e073.cloud.databricks.com/#notebook/26953/command/26967

Some key takeaways:
- About 20% of pings are affected
- Whether there is a difference depends strongly on the subsessionCounter indicated in the ping; there is never a difference if subsessionCounter is <= 2 and there is always a difference if subsessionCounter is > 3.
- The relationship between subsessionLength and activeTicks is different between the simpleMeasurement and the scalar; for the simpleMeasurement, the relationship between session length and ticks recorded depends on the subsessionCounter. For the scalar, the relationship between subsessionLength and activeTicks is relatively independent of the subsession counter. To me, this suggests that the simpleMeasurement is not being reset correctly between subsessions.

Comment 1

[Chris H-C :chutten]

The code for browser.engagement.active_ticks is here: https://searchfox.org/mozilla-central/rev/aff5d4ad5d7fb2919d267cbc23b1d87ae3cf0110/toolkit/components/telemetry/TelemetrySession.jsm#1669
The code for caclulating simplemeasurement's activeTicks is here: https://searchfox.org/mozilla-central/rev/aff5d4ad5d7fb2919d267cbc23b1d87ae3cf0110/toolkit/components/telemetry/TelemetrySession.jsm#806-815

active_ticks is so simply implemented it is difficult to see a case where it might be erroneous. It counts active tick intervals and is reset to 0 whenever all scalars are reset to 0 (when a subsession ends). I think it's probably the simpleMeasurement that is incorrect.

The way I interpret the simpleMeasurements code is that there is a timeline of active ticks, monotonically increasing throughout the session (_sessionActiveTicks). Every subsession we need a pointer into that timeline to see where this subsession's timeline started (this is _subsessionStartActiveTicks) so that when it ends we can see how many active ticks have passed since the subsession started (_sessionActiveTicks - _subsessionStartActiveTicks)

The problem seems to be when (isSubsession && clearSubsession). At that point we seem to be setting _subsessionStartActiveTicks  _pointer_ to be the _count of how many_ activeTicks there were in the previous subsession.

An example!

Subsession 1:
_sessionActiveTicks = _subsessionStartActiveTicks = 0;
Then 400 active ticks happen.
subsession 1 ends with _sessionActiveTicks = 400, _subsessionStartActiveTicks = 0
We report activeTicks = 400
We set _subsessionStartActiveTicks to 400
Subsession 2:
100 active ticks happen.
subsession 2 ends _sessionActiveTicks = 500, _subsessionStartActiveTicks = 400
We report activeTicks = 100
We set _subsessionStartActiveTicks to 100 <<<<<<<<<<<<<<<<<<<<<<<< HERE'S THE PROBLEM

This only becomes a problem when reporting the activeTicks for subsession 3 and up (for each session) and will result in a activeTicks value always equaling or exceeding the active_ticks value.

Pretty sure we can fix this by 
-      this._subsessionStartActiveTicks = activeTicks;
+      this._subsessionStartActiveTicks = this._sessionActiveTicks;

Comment 2

[Chris H-C :chutten]

(if this theory is correct, this data fault dates back to when the subsession-based activeTicks simple measurement was added in bug 1137222 for Firefox 39)

Comment 3

[Chris H-C :chutten]

Attachment: bug 1482466 - Ensure subsession activeTicks are correct in simpleMeasurements r?Dexter

Comment 4

[Alessio Placitelli [:Dexter]]

Comment on attachment 8999282 [details]
bug 1482466 - Ensure subsession activeTicks are correct in simpleMeasurements r?Dexter

Alessio Placitelli [:Dexter] has approved the revision.

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6b4359d502be
Ensure subsession activeTicks are correct in simpleMeasurements r=Dexter

Comment 6

[Natalia Csoregi [:nataliaCs]]

Backed out for test_TelemetrySession_activeTicks.js failures.

backout: https://hg.mozilla.org/integration/autoland/rev/2f02edc7acc480c0d79cae848a6f1fc5332eec32

push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=6b4359d502be4882df3a9f6f38da2796901e5280

failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=193657087&repo=autoland&lineNumber=1609

[task 2018-08-13T14:42:26.646Z] 14:42:26     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js
[task 2018-08-13T14:42:58.126Z] 14:42:58  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | xpcshell return code: 0
[task 2018-08-13T14:42:58.126Z] 14:42:58     INFO -  TEST-INFO took 31480ms
[task 2018-08-13T14:42:58.128Z] 14:42:58     INFO -  >>>>>>>
[task 2018-08-13T14:42:58.128Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | xpcw: cd /sdcard/tests/xpc/toolkit/components/telemetry/tests/unit
[task 2018-08-13T14:42:58.128Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | xpcw: xpcshell -r /sdcard/tests/xpc/c/httpd.manifest --greomni /data/local/xpcb/target.apk -m -s -e const _HEAD_JS_PATH = "/sdcard/tests/xpc/head.js"; -e const _MOZINFO_JS_PATH = "/sdcard/tests/xpc/p/mozinfo.json"; -e const _TESTING_MODULES_DIR = "/sdcard/tests/xpc/m"; -f /sdcard/tests/xpc/head.js -e const _SERVER_ADDR = "localhost" -e const _HEAD_FILES = ["/sdcard/tests/xpc/toolkit/components/telemetry/tests/unit/head.js"]; -e const _JSDEBUGGER_PORT = 0; -e const _TEST_FILE = ["test_TelemetrySession_activeTicks.js"]; -e const _TEST_NAME = "toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js" -e _execute_test(); quit(0);
[task 2018-08-13T14:42:58.128Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | [3212, Unnamed thread 46b0e080] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 209
[task 2018-08-13T14:42:58.129Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | [3212, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2717
[task 2018-08-13T14:42:58.129Z] 14:42:58     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2018-08-13T14:42:58.129Z] 14:42:58     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2018-08-13T14:42:58.130Z] 14:42:58     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2018-08-13T14:42:58.130Z] 14:42:58     INFO -  running event loop
[task 2018-08-13T14:42:58.130Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | Starting test_setup
[task 2018-08-13T14:42:58.131Z] 14:42:58     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2018-08-13T14:42:58.131Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | [3212, Main Thread] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/workspace/build/src/gfx/gl/GLContextFeatures.cpp, line 915
[task 2018-08-13T14:42:58.132Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | [3212, Main Thread] WARNING: Vsync not supported. Falling back to software vsync: file /builds/worker/workspace/build/src/gfx/thebes/gfxAndroidPlatform.cpp, line 402
[task 2018-08-13T14:42:58.132Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | JavaScript strict warning: resource://gre/modules/TelemetryEnvironment.jsm, line 1430: ReferenceError: reference to undefined property "@mozilla.org/sandbox/sandbox-settings;1"
[task 2018-08-13T14:42:58.133Z] 14:42:58     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2018-08-13T14:42:58.133Z] 14:42:58     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2018-08-13T14:42:58.133Z] 14:42:58     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2018-08-13T14:42:58.134Z] 14:42:58     INFO -  "CONSOLE_MESSAGE: (info) 1534171352651	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor"
[task 2018-08-13T14:42:58.134Z] 14:42:58     INFO -  "CONSOLE_MESSAGE: (info) 1534171353150	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected."
[task 2018-08-13T14:42:58.134Z] 14:42:58     INFO -  "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "@mozilla.org/sandbox/sandbox-settings;1"" {file: "resource://gre/modules/TelemetryEnvironment.jsm" line: 1430}]"
[task 2018-08-13T14:42:58.135Z] 14:42:58     INFO -  "CONSOLE_MESSAGE: (info) 1534171353380	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2018-08-13T14:42:58.136Z] 14:42:58     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession_activeTicks.js | [3212, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004002: file /builds/worker/workspace/build/src/toolkit/components/resistfingerprinting/nsRFPService.cpp, line 682
[task 2018-08-13T14:42:58.136Z] 14:42:58     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1534171354326	Toolkit.Telemetry	ERROR	TelemetryEnvironment::EnvironmentCache - error while initializing: TypeError: gShutdownBarrier is null(resource://gre/modules/AddonManager.jsm:3472:5) JS Stack trace: get [e-mail]:3472:5
[task 2018-08-13T14:42:58.137Z] 14:42:58     INFO -  [e-mail]:502:7
[task 2018-08-13T14:42:58.138Z] 14:42:58     INFO -  [e-mail]:896:9
[task 2018-08-13T14:42:58.138Z] 14:42:58     INFO -  [e-mail]:59:26
[task 2018-08-13T14:42:58.138Z] 14:42:58     INFO -  [e-mail]:70:12
[task 2018-08-13T14:42:58.139Z] 14:42:58     INFO -  [e-mail]:336:10
[task 2018-08-13T14:42:58.139Z] 14:42:58     INFO -  test_setup@test_TelemetrySession_activeTicks.js:12:9
[task 2018-08-13T14:42:58.140Z] 14:42:58     INFO -  run_next_test/_run_next_test/<@head.js:1441:22
[task 2018-08-13T14:42:58.140Z] 14:42:58     INFO -  [e-mail]:1441:10
[task 2018-08-13T14:42:58.141Z] 14:42:58     INFO -  [e-mail]:692:9
[task 2018-08-13T14:42:58.141Z] 14:42:58     INFO -  [e-mail]:219:3
[task 2018-08-13T14:42:58.141Z] 14:42:58     INFO -  [e-mail]:533:5
[task 2018-08-13T14:42:58.142Z] 14:42:58     INFO -  @-e:1:1" {file: "resource://gre/modules/Log.jsm" line: 684}]
[task 2018-08-13T14:42:58.142Z] 14:42:58     INFO -  append@resource://gre/modules/Log.jsm:684:9
[task 2018-08-13T14:42:58.142Z] 14:42:58     INFO -  log@resource://gre/modules/Log.jsm:365:7
[task 2018-08-13T14:42:58.143Z] 14:42:58     INFO -  getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:489:14
[task 2018-08-13T14:42:58.144Z] 14:42:58     INFO -  error@resource://gre/modules/Log.jsm:373:5
[task 2018-08-13T14:42:58.144Z] 14:42:58     INFO -  EnvironmentCache/this._initTask<@resource://gre/modules/TelemetryEnvironment.jsm:922:9
[task 2018-08-13T14:42:58.144Z] 14:42:58     INFO -  _do_main@/sdcard/tests/xpc/head.js:219:3
[task 2018-08-13T14:42:58.145Z] 14:42:58     INFO -  _execute_test@/sdcard/tests/xpc/head.js:533:5

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/07bf059b5493
Ensure subsession activeTicks are correct in simpleMeasurements r=Dexter

Comment 8

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/07bf059b5493

Comment 9

[Chris H-C :chutten]

Comment on attachment 8999282 [details]
bug 1482466 - Ensure subsession activeTicks are correct in simpleMeasurements r?Dexter

Approval Request Comment
[Feature/Bug causing the regression]:
bug 1137222
[User impact if declined]:
activeTicks from pings without the active_ticks scalar (2-3% of pings per day) can be over-reported
[Is this code covered by automated tests?]:
Yes.
[Has the fix been verified in Nightly?]:
Yes. I cloned :tdsmith's analysis and ran it on the 8.3k pings provided by Nightly so far and none of them have any difference between activeTicks and active_ticks regardless of subsession_counter. I will file a follow-up to validate the fix in a week.
[Needs manual test from QE? If yes, steps to reproduce]: 
No.
[List of other uplifts needed for the feature/fix]:
None.
[Is the change risky?]:
No.
[Why is the change risky/not risky?]:
Few pings are affected (2-3%) and activeTicks isn't widely used (it was suspected of being unsuitable in the past, so Data Lore restricted its adoption) and now we have an automated test.
[String changes made/needed]:
None.

Comment 10

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8999282 [details]
bug 1482466 - Ensure subsession activeTicks are correct in simpleMeasurements r?Dexter

Fix for telemetry accuracy, adds a test; let's uplift for beta 18.

Comment 11

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/releases/mozilla-beta/rev/a8ec1cd112b3