1882110 - Investigate invalidState errors in new GeckoView pure glean metrics

Status: RESOLVED FIXED

(Data Platform and Tools :: Monitoring & Alerting, defect)

Description

[Perry McManis [:perry.mcmanis]]

We recently migrated these metric from Geckoview Streaming to a pure Glean impl. We are now seeing errors on Fenix. Speculatively, we may not have seen them before because they were truncated inside of Legacy before being passed to Glean.

Investigate what's going on with these fields:

• Geckoview.page_load_time is spiking InvalidState errors since Feb. 22 (affecting 1.5% of the population)
• Geckoview.page_reload_time InvalidState errors also increasing, but to a lesser degree.

Comment 1

[Perry McManis [:perry.mcmanis]]

It's possible this was always happening and error hand-off was ???? due to it being GVST

FWIW I have confirmed that we collected data in this metric before migration:

SELECT
  m.client_info.client_id,
  submission_timestamp,
  ARRAY_LENGTH(metrics.timing_distribution.geckoview_page_load_time.values) as kv_pair_counts,
  client_info.app_display_version
  -- plt.*
FROM
  org_mozilla_firefox.metrics AS m
-- cross join
--  unnest (metrics.timing_distribution.geckoview_page_load_time.values) as plt
WHERE
  DATE(submission_timestamp) >= DATE_SUB(CURRENT_DATE(), INTERVAL 60 DAY)
  and ARRAY_LENGTH(metrics.timing_distribution.geckoview_page_load_time.values) > 0
  and mozfun.norm.extract_version(client_info.app_display_version, "major") < 124
  and mozfun.norm.extract_version(client_info.app_display_version, "major") > 120

LIMIT 100

This error occurs when .finish() is called, when I look at the code it appears that start() should HAVE to get called for us to get to the Glean call site, so I need to investigate what might be going on.

Thoughts:
ID collision? start twice, but only one id, try to cancel twice? seems unlikely

starting glean failed?

  start() {
    if (this.isRunning()) {
      this.cancel();
    }
    this._timerId = this._metric.start();
  }

pretty straightforward, so maybe we're failing inside of .start() OR maybe this.isRunning() isn't always cleared correctly

Comment 2

[Perry McManis [:perry.mcmanis]]

After some discussion, the possibility of having the same timerID on multiple instances of ProgressTracker may actually have more realistic than I initially thought.

It's not very likely that this is being caused by Glean itself. If we take a look at start() for a timingDistribution's timer in the code, we see that we are incrementing IDs atomically and we have good reason to believe this is quite reliable.

I'd like to test if my premise is possible (and maybe even morph into a fix for this) by keeping a set of timerIDs and inside of ProgressTracker.start() guarantee that whatever timerID is generated by the stopwatch pattern is unique, (eventually, if not then ask for a new one). I think if we can find some evidence this is happening, then the fix may follow the same pattern (question mark, happy to get input on how best to actually do this if we need to make it more permanent).

:owlish since you reviewed chutten's patch I have tagged you, please feel free to direct me to someone else though!

My specific questions:

• Does the premise multiple progress trackers : a single id seem reasonably possible?
• Is my proposed idea for finding/solving this reasonable?

Comment 3

[Perry McManis [:perry.mcmanis]]

Attachment: duplicateTimerId.png

OK I believe I have found evidence that we are indeed attaching the same timerID to multiple instances of the gleanStopwatch/progressTracker which may mean that we are calling cancel/stopAndAccumulate multiple times on a single timerID, which would indeed lead to an invalidState error.

Comment 4

[Perry McManis [:perry.mcmanis]]

Attachment: WIP: Bug 1882110 - Instrument cases of duplicated timerIDs for some Geckoview timing distributions r?chutten

Comment 5

[Perry McManis [:perry.mcmanis]]

Attachment: null to zero

Update: reports of duplicated timerIDs via the interface were a bit premature.

It turns out that a far more likely culprit is that null is cast to 0 internally for stopAndAccumulate() and cancel() meaning that when you feed null to these methods, they try to end the metric for id 0 instead.

See the screenshot for an idea of how to invoke this behavior.

Comment 6

[Perry McManis [:perry.mcmanis]]

Attachment: Bug 1882110 - Gaurd stop and cancel stopwatch methods to avoid invalidState r?chutten

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/27c619c9ef19
Gaurd stop and cancel stopwatch methods to avoid invalidState r=chutten,geckoview-reviewers,m_kato

Comment 8

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/27c619c9ef19