1021922 - Record telemetry for browser database operations

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Data Providers, defect)

Description

[Richard Newman [:rnewman]]

As far as I can tell, we don't do this, so we don't know how much time we spend in awesomebar queries, recording history items, etc.

We should, so we know how to prioritize performance work.

There's a related set of bugs that I won't file yet, which is a task-oriented version of this: how long does it take to show awesomebar results after the user presses a key? Etc.

I'd like for us to get this into 32.

Comment 1

[Richard Newman [:rnewman]]

Oh hey, we already have at least one relevant unused histogram:

  "FENNEC_AWESOMEBAR_ALLPAGES_EMPTY_TIME": {
    "expires_in_version": "never",
    "kind": "exponential",
    "low": 10,
    "high": "20000",
    "n_buckets": 20,
    "description": "Fennec: Time for the Awesomebar Top Sites query to return with no filter set (ms)",
    "cpp_guard": "ANDROID"
  },

Comment 2

[Richard Newman [:rnewman]]

Attachment: Record telemetry for browser database operations. v1

Who should I tag for a sanity check on Histogram.json?

Comment 3

[Richard Newman [:rnewman]]

Attachment: Record telemetry for browser database operations. v2

Verified this patch by hand.

Comment 4

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 8437416 [details] [diff] [review]
Record telemetry for browser database operations. v2

Looks OK. I wouldn't mind seeing the Log.d calls removed. I think we are getting too chatty in logcat.

Also, see bug 966485 for cleanup/fixup too. I believe we don't think we can track about:home startup speed anymore.

Comment 5

[Richard Newman [:rnewman]]

Pushed without logging:

https://hg.mozilla.org/integration/fx-team/rev/515dbeff1513

Comment 6

[Geoff Brown [:gbrown]]

I noticed debug logging in https://tbpl.mozilla.org/php/getParsedLog.php?id=41472231&tree=Fx-Team:

14:25:47     INFO -  06-10 14:21:05.933 D/GeckoGlobalHistory(  424): GlobalHistory.add took 4771msec.
14:25:47     INFO -  06-10 14:21:05.963 D/GeckoGlobalHistory(  424): GlobalHistory.update took 36msec.
14:25:47     INFO -  06-10 14:21:06.003 D/GeckoGlobalHistory(  424): GlobalHistory.add took 37msec.
14:25:47     INFO -  06-10 14:21:06.043 D/GeckoGlobalHistory(  424): GlobalHistory.update took 40msec.
14:25:47     INFO -  06-10 14:21:06.043 W/GeckoGlobalHistory(  424): Rebuilding visited link set...
14:25:47     INFO -  06-10 14:21:06.742 D/GeckoGlobalHistory(  424): GlobalHistory.add took 26msec.
14:25:47     INFO -  06-10 14:21:13.502 D/GeckoGlobalHistory(  424): GlobalHistory.update took 6509msec.
14:25:47     INFO -  06-10 14:21:13.532 D/GeckoGlobalHistory(  424): GlobalHistory.add took 35msec.
14:25:47     INFO -  06-10 14:21:13.542 D/GeckoGlobalHistory(  424): GlobalHistory.update took 12msec.
14:25:47     INFO -  06-10 14:21:13.582 D/GeckoGlobalHistory(  424): GlobalHistory.add took 32msec.
14:25:47     INFO -  06-10 14:21:13.642 D/GeckoGlobalHistory(  424): GlobalHistory.update took 58msec.
14:25:47     INFO -  06-10 14:21:13.652 W/GeckoGlobalHistory(  424): Rebuilding visited link set...
14:25:47     INFO -  06-10 14:21:20.412 D/GeckoGlobalHistory(  424): GlobalHistory.add took 4333msec.
14:25:47     INFO -  06-10 14:21:20.432 D/GeckoGlobalHistory(  424): GlobalHistory.update took 19msec.
14:25:47     INFO -  06-10 14:21:20.452 D/GeckoGlobalHistory(  424): GlobalHistory.add took 28msec.
14:25:47     INFO -  06-10 14:21:20.472 D/GeckoGlobalHistory(  424): GlobalHistory.update took 15msec.
14:25:47     INFO -  06-10 14:21:20.512 D/GeckoGlobalHistory(  424): GlobalHistory.add took 38msec.
14:25:47     INFO -  06-10 14:21:20.532 D/GeckoGlobalHistory(  424): GlobalHistory.update took 20msec.

Is everything okay there? (Noticed this in bug 1023568.)

Comment 7

[Richard Newman [:rnewman]]

Piss, missed touching one file when I reduced logging. Will land a follow-up.

But still, leaving in the logging is useful: those are some terrifying extremes, and some disappointing averages!

Comment 8

[Richard Newman [:rnewman]]

Follow-up: https://hg.mozilla.org/integration/fx-team/rev/d51f3d0e2238

Comment 9

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/515dbeff1513

Comment 10

[Richard Newman [:rnewman]]

Comment on attachment 8437416 [details] [diff] [review]
Record telemetry for browser database operations. v2

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
  None. We want more data on browser DB perf issues.

User impact if declined: 
  None.

Testing completed (on m-c, etc.): 
  Landed on m-c. Tested locally.

Risk to taking this patch (and alternatives if risky): 
  Should be slim. Adds new histograms and writes to them.

String or IDL/UUID changes made by this patch:
  None.

Comment 11

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/d51f3d0e2238

Comment 12

[Richard Newman [:rnewman]]

Update on approval request?

Comment 13

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8437416 [details] [diff] [review]
Record telemetry for browser database operations. v2

Aurora approval granted. (Sorry for the delay.) Thanks for cleaning up some unused Telemetry probes.

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/75979b9fa1f3