Closed Bug 1129029 Opened 5 years ago Closed 5 years ago

Telemetry probes for reader mode performance

Categories

(Toolkit :: Reader Mode, defect, P2)

defect

Tracking

()

RESOLVED FIXED
mozilla40
Iteration:
40.3 - 11 May
Tracking Status
firefox38.0.5 --- fixed
firefox39 --- fixed
firefox40 --- fixed

People

(Reporter: Margaret, Assigned: Margaret)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 1 obsolete file)

We should add some telemetry probes to figure out how long different reader mode interactions take. Some probes to start with:

* Time for download article XHR (inspired by bug 1127627)
* Time to save to/read from cache
* Size of cache (related to bug 1126244)
Flags: firefox-backlog+
Priority: -- → P2
Assignee: nobody → hammerly.matt
Status: NEW → ASSIGNED
(In reply to :Margaret Leibovic from comment #0)

> * Time to save to/read from cache
> * Size of cache (related to bug 1126244)

We don't actually use this cache on desktop, so while this would be useful for Android, it might not be a top priority.

Other things that could be interesting to measure:

* Time to serialize the DOM in ReaderMode._readerParse()
* Time for JSDOMParser.parse()
* Time for Readability.parse()
Assignee: hammerly.matt → nobody
Status: ASSIGNED → NEW
Assignee: nobody → margaret.leibovic
Gijs and Niko have a holiday tomorrow, so maybe dolske can provide some feedback :)

I wanted to add more granular probes around JSDOMParser and Readability, but we don't have access to Components in the reader worker, so I would have to do something fancier to record things in telemetry. However, this is probably good enough for our purposes.

I totally guessed at values to put in the histograms, so I'm open to feedback there.

I also wonder if we should add a probe to see how often we show the reader view button.

At a higher level, what questions are we hoping to answer with telemetry? The probes here should help us create charts that tell us if we're trending more or less successful over time when hitting the reader view button, as well as whether we suffer any performance issues, but are there other questions we would like answered?
Attachment #8600093 - Flags: feedback?(dolske)
Comment on attachment 8600093 [details] [diff] [review]
WIP - Telemetry probes for reader mode performance

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

::: toolkit/components/reader/ReaderMode.jsm
@@ +165,2 @@
>      let doc = yield this._downloadDocument(url);
> +    TelemetryStopwatch.finish("READER_MODE_DOWNLOAD_MS");

It might be nice to split these out into success/error cases -- especially since some of the long measurements will probably be to timeouts. But I'd expect those to be a small percentage of measurements, and so doesn't really matter much. And it's still an accurate measurement of overall UX from the user's POV.

Maybe just add counters for the error/nodoc/success cases in _downloadDocument?

::: toolkit/components/telemetry/Histograms.json
@@ +8012,5 @@
> +    "kind": "exponential",
> +    "high": "10000",
> +    "n_buckets": 15,
> +    "description": "Time (ms) for the reader worker to parse a document"
> +  },

I'd probably double n_buckets of these two probes to 30, just to get a little finer resolution.

@@ +8018,5 @@
> +    "expires_in_version": "50",
> +    "kind": "exponential",
> +    "low": 50,
> +    "high": "40000",
> +    "n_buckets": 15,

And quadruple this one (to 60), to get better resolution over the wider range.
Attachment #8600093 - Flags: feedback?(dolske) → feedback+
I added a probe for the download result, and I updated the parse result probe to be an enum to tell us more about why it might have failed.
Attachment #8600093 - Attachment is obsolete: true
Attachment #8601698 - Flags: review?(dolske)
Comment on attachment 8601698 [details] [diff] [review]
Telemetry probes for reader mode performance

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

driveby r+ with issues noted below.

::: toolkit/components/reader/ReaderMode.jsm
@@ +176,2 @@
>      let doc = yield this._downloadDocument(url);
> +    TelemetryStopwatch.finish("READER_MODE_DOWNLOAD_MS");

Please add a catch handler to the async task that also does this, or we'll have unbalanced start/end things if the downloaddocument yield rejects.

@@ +323,3 @@
>      let serializer = Cc["@mozilla.org/xmlextras/xmlserializer;1"].
>                       createInstance(Ci.nsIDOMSerializer);
>      let serializedDoc = yield Promise.resolve(serializer.serializeToString(doc));

I wonder if this can throw.

@@ +323,4 @@
>      let serializer = Cc["@mozilla.org/xmlextras/xmlserializer;1"].
>                       createInstance(Ci.nsIDOMSerializer);
>      let serializedDoc = yield Promise.resolve(serializer.serializeToString(doc));
> +    TelemetryStopwatch.finish("READER_MOD_SERIALIZE_DOM_MS");

I've never really understood the yield here. It will let the event loop breathe, I guess, but nothing else, and I doubt that the XML serialization actually takes that much time - we could make this measurement more accurate by factoring out the serialization to happen as a local variable assignment. Right now we'll also count the time until the yield returns. Not sure that's intended.

::: toolkit/components/telemetry/Histograms.json
@@ +8009,5 @@
>      "kind": "count",
>      "description": "Tracking whether a ServiceWorker spawn gets queued due to hitting max workers per domain limit"
> +  },
> +  "READER_MODE_SERIALIZE_DOM_MS": {
> +    "expires_in_version": "50",

Copy-paste-from-the-existing-histograms-alert! :-)

Why version 50? Seems like we should have enough data by 42, tbh, to know if we desperately want to keep working on perf or not.
Attachment #8601698 - Flags: review?(dolske) → review+
(In reply to :Gijs Kruitbosch from comment #5)
> Comment on attachment 8601698 [details] [diff] [review]
> Telemetry probes for reader mode performance
> 
> Review of attachment 8601698 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> driveby r+ with issues noted below.
> 
> ::: toolkit/components/reader/ReaderMode.jsm
> @@ +176,2 @@
> >      let doc = yield this._downloadDocument(url);
> > +    TelemetryStopwatch.finish("READER_MODE_DOWNLOAD_MS");
> 
> Please add a catch handler to the async task that also does this, or we'll
> have unbalanced start/end things if the downloaddocument yield rejects.

Good catch (ha ha).

> @@ +323,3 @@
> >      let serializer = Cc["@mozilla.org/xmlextras/xmlserializer;1"].
> >                       createInstance(Ci.nsIDOMSerializer);
> >      let serializedDoc = yield Promise.resolve(serializer.serializeToString(doc));
> 
> I wonder if this can throw.

I don't see anything in the IDL docs about it throwing:
http://mxr.mozilla.org/mozilla-central/source/dom/base/nsIDOMSerializer.idl#29

I also don't see anything mentioned on MDN, so I think it's ok to assume this won't throw.

> @@ +323,4 @@
> >      let serializer = Cc["@mozilla.org/xmlextras/xmlserializer;1"].
> >                       createInstance(Ci.nsIDOMSerializer);
> >      let serializedDoc = yield Promise.resolve(serializer.serializeToString(doc));
> > +    TelemetryStopwatch.finish("READER_MOD_SERIALIZE_DOM_MS");
> 
> I've never really understood the yield here. It will let the event loop
> breathe, I guess, but nothing else, and I doubt that the XML serialization
> actually takes that much time - we could make this measurement more accurate
> by factoring out the serialization to happen as a local variable assignment.
> Right now we'll also count the time until the yield returns. Not sure that's
> intended.

Yoric suggested adding this in this bug 1140172 comment 6, and I just implemented this without questioning it. But yes, good point... for the sake of telemetry accuracy, I'll just remove this yield.

> ::: toolkit/components/telemetry/Histograms.json
> @@ +8009,5 @@
> >      "kind": "count",
> >      "description": "Tracking whether a ServiceWorker spawn gets queued due to hitting max workers per domain limit"
> > +  },
> > +  "READER_MODE_SERIALIZE_DOM_MS": {
> > +    "expires_in_version": "50",
> 
> Copy-paste-from-the-existing-histograms-alert! :-)
> 
> Why version 50? Seems like we should have enough data by 42, tbh, to know if
> we desperately want to keep working on perf or not.

I'll admit this was a pretty arbitrary choice. My fear with choosing a low version is that we might implement fixes later, but we can always increase this (right?) if we decide to continue working on this.
(In reply to :Margaret Leibovic from comment #6)
> (In reply to :Gijs Kruitbosch from comment #5)
> > Copy-paste-from-the-existing-histograms-alert! :-)
> > 
> > Why version 50? Seems like we should have enough data by 42, tbh, to know if
> > we desperately want to keep working on perf or not.
> 
> I'll admit this was a pretty arbitrary choice. My fear with choosing a low
> version is that we might implement fixes later, but we can always increase
> this (right?) if we decide to continue working on this.

That is my understanding, but it's probably worth checking with someone who knows telemetry better.
Comment on attachment 8601698 [details] [diff] [review]
Telemetry probes for reader mode performance

(Requesting for 38.0.5)

Approval Request Comment
[Feature/regressing bug #]: Reader View

[User impact if declined]: We won't have data about the performance of our Reader View logic, which will make it hard to measure potential improvements

[Describe test coverage new/current, TreeHerder]: Just landed on fx-team

[Risks and why]: Low-risk, adds telemetry probes without changing logic

[String/UUID change made/needed]: none
Attachment #8601698 - Flags: approval-mozilla-release?
Attachment #8601698 - Flags: approval-mozilla-aurora?
https://hg.mozilla.org/mozilla-central/rev/4dc08dfc1fbf
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla40
Iteration: --- → 40.3 - 11 May
Flags: qe-verify?
Attachment #8601698 - Flags: approval-mozilla-release?
Attachment #8601698 - Flags: approval-mozilla-release+
Attachment #8601698 - Flags: approval-mozilla-aurora?
Attachment #8601698 - Flags: approval-mozilla-aurora+
Depends on: 1204900
You need to log in before you can comment on or make changes to this bug.