1414959 - Android Fennec telemetry sending multiples of 10 core pings per client-day at greater than expected frequency

Status: RESOLVED INCOMPLETE

(Firefox for Android Graveyard :: Metrics, enhancement, P3)

Description

[Frank Bertsch [:frank]]

This plot gives number of pings per client-day for our mobile applications (core ping only!) [0]. As expected, it's a monotonically decreasing amount; mostly we see one ping per client-day, we see less two pings per client-day, etc. But for Android-Fennec ONLY, we see multiples of ten at high frequencies - e.g. 10, 20, etc.

This must be an artifact of the telemetry system used by Fennec, and I'm worried it could be messing up the numbers. For example, is this extra data being reported, that doesn't mean real usage? Or is other data being dropped to cause this?

Next steps are to get some hypotheses from client engineers. If we can verify them from the data that would be helpful, otherwise we'll have to experiment from clients.

[0] https://sql.telemetry.mozilla.org/queries/48672#131238

Comment 1

[Richard Newman [:rnewman]]

We have a hard limit of 40 ping files stored.

We upload if 12 hours have elapsed since the last.

The number of Sync pings and events factor into whether an upload occurs.

We should be sending a core ping each time BrowserApp opens. The question is then: how do these things (and others?) tie together to cause spikes?

Comment 2

[:Grisha Kruglov]

I've re-run the query for the period of time before sync ping landed, and the general shape is the same - spikes at multiples of 10. That's just with the core ping being submitted from Fennec's java telemetry, which I think lets us ignore sync ping during a first pass of this.

TLDR: I'm not sure why this happens (I'm not familiar w/ our Distribution etc code), but I'm not surprised that it does happen. After reading this code a bit, ISTM that we're almost guaranteed to do some subtly wrong thing, somewhere.

We try to submit a core ping both in BrowserApp's onStart and onStop (during first run).

Core ping submissions are tightly coupled to SearchEngineManager (we need to know the default search manager), which is coupled to figuring out what our Distribution is. All of this code is mostly callback driven - some callback queues are maintained until distribution is init'd.

I'm reading through the SearchEngineManager and Distribution code for the first time, and at first glance it seems a bit bonkers (or at least, convoluted - Distribution.java is essentially a state machine, but is eerily similar to a spaghetti dish in its structure).

Distribution maintains two callback queues - 'ready' and 'late'.

When we attempt to upload a core ping, we ask SearchEngineManager to process our 'upload callback' once it figures out what is the search engine. If SearchEngineManager knows, it runs our upload callback right away. Otherwise, it asks Distribution class to conditionally schedule the callback on its 'ready' queue if it didn't finish doInit() yet, or run through our callback based on what its STATE is. If the state is STATE_NONE, callback's distributionNotFound will be invoked, but it will _also_ be placed on the 'late' queue if 'shouldDelayLateCallbacks === true'. However, shouldDelayLateCallbacks is defined such that it's TRUE iff state = STATE_NONE: https://dxr.mozilla.org/mozilla-central/source/mobile/android/base/java/org/mozilla/gecko/distribution/Distribution.java#518

Meaning that we'll always do both: run callback's distributionNotFound AND schedule callback for execution on the 'late' queue.

However, SearchEngineManager's implementation of the callback will perform largely the same work in all cases: https://dxr.mozilla.org/mozilla-central/source/mobile/android/base/java/org/mozilla/gecko/search/SearchEngineManager.java?q=path%3ASearchEngineManager.java&redirect_type=single#220

Meaning that whichever method of this callback is executed, it'll end up running through TelemetryCorePingDelegate's 'execute' method - which queues ping for an upload.

So that gets us to "multiples of 2", at the very least - IF the 'late' queue is eventually processed. On a first run, we'll also try to 'uploadPing' in 'onStop' (not just 'onStart'), and depending on when those lifecycle events happen in relation to Distribution events, it seems possible we'll end up queuing from 1 to 4 core pings for one Fennec launch. It's hard to reason about this precisely.

As far as I can tell, we process the 'late' queue once we receive com.android.vending.INSTALL_REFERRER broadcast intent, and the referrer 'campaign' is set to "distribution". Once we receive this intent, we'll run through our 'late' queue and possibly queue a core ping for submission. We'll also perform _another_ call to distribution.doInit (https://dxr.mozilla.org/mozilla-central/source/mobile/android/base/java/org/mozilla/gecko/distribution/Distribution.java#327). Our state will be STATE_SET, and so the doInit() will just run through the 'ready' queue. If that queue somehow contains another Core ping callback, we'll queue another ping for submission. This might be possible if onStart & onStop calls happened in quick succession - but that seems non-deterministic, I'm not sure we'll ever get a chance to actually finish up before being killed by the OS.

Also note that a lot of this logic depends on Distribution's 'state' being sane. It's marked as 'volatile' - supposedly we check and update it from different threads. However, Distribution's read/write of 'state' looks pretty suspect. In doInit(), it does something like:

```
state = persistedStateValue or UNKNOWN
if (state == NONE) {
 doStuff && return;
}
if (state == SET) {
 doStuff && return;
}
doMoreStuff
state = SET or NONE
persistStateValue
```

And in processDelayedReferrer(ref) it'll do:

```
if (state != NONE) { return }
state = SET
```

None of this code is synchronized, so it seems like there's room for race conditions here, which might also lead to strange behaviors.


---- 



ANOTHER side of this is the actual core ping submission, which also seems wrong - but in a more straightforward way. It uses a directory with bunch of JSON files in it, one for each queued core ping. When a ping is queued for upload, it's first stored in json file, and then we immediately attempt to upload currently queued pings. Uploader essentially reads list of files, reads every file, and performs a separate upload for each. When upload succeeds, successful pings are deleted.

Now, consider what happens when we queue two core pings for upload in quick succession. We'll write both of them to disk - two JSON files - and launch two instances of the upload service. Then depending on timing of when these UploadServices launch, they'll process from 0 to 2 files each (and so perform 0 to 2 uploads each).

If the telemetry server then dupes submitted core pings by their UID - that is, if the upload of a core ping is idempotent - we're safe. Otherwise, we'll produce duplicate submissions.

So overall I'm not surprised we're doing something wrong, but I'm not yet sure how we get spikes around multiples of 10.

Comment 3

[:Grisha Kruglov]

Frank, when does de-duping of submitted pings happen in the pipeline? Does this graph plot submissions after dupes have been accounted for?

Also, what's the state of the de-duping work? Last I checked, the pipeline wasn't 100% successful in de-duping ping submissions.

Comment 4

[Frank Bertsch [:frank]]

De-duping happens before the data hits this dataset, but you're correct that we are not 100% successful. We catch most duplicates that occur within 4 hours, so ~65%.

Comment 5

[:Grisha Kruglov]

We can start with some concrete improvements around races in ping submissions as per Comment 2 - see last part of that comment. Unfortunately I don't have a lot of time to tackle them now; I'll keep this bug on the list of things to do "on a side".

As long as we're de-duping pings with a generally good success rate, I don't think this will affect numbers in our dashboards too much. If that's right, the main gains here are client resource improvements - use less battery and less bandwidth by avoiding unnecessary work (e.g. submission races might result in re-submitting a ping we've already submitted).

Comment 6

[Michael Comella (:mcomella) [NI reported issues only: ex-Mozilla]]

[triage] Potentially critical - core ping data may be inaccurate. Susheel, do you have any thoughts? Note that solving this would be hairy - see comment 2 for an example.

Comment 7

[:sdaswani]

yes potentially critical

Comment 8

[Sylvestre Ledru [:Sylvestre]]

Moving to p3 because no activity for at least 24 weeks.

Comment 9

[BMO Automation]

We have completed our launch of our new Firefox on Android. The development of the new versions use GitHub for issue tracking. If the bug report still reproduces in a current version of [Firefox on Android nightly](https://play.google.com/store/apps/details?id=org.mozilla.fenix) an issue can be reported at the [Fenix GitHub project](https://github.com/mozilla-mobile/fenix/). If you want to discuss your report please use [Mozilla's chat](https://wiki.mozilla.org/Matrix#Connect_to_Matrix) server https://chat.mozilla.org and join the [#fenix](https://chat.mozilla.org/#/room/#fenix:mozilla.org) channel.