1387625 - TIME_TO_DOM_LOADING_MS telemetry probe is not reporting as many samples as expected

Status: RESOLVED FIXED

(Toolkit :: Performance Monitoring, enhancement)

Description

[Chris Peterson [:cpeterson]]

The telemetry sample counts for the various TIME_TO_DOM_*_MS telemetry probes are not exactly the same. IIUC, every (successful) page load passes through each of these loading states and thus we should expect exactly same number of DOM_LOADING samples as DOM_COMPLETE samples. But I see the following sample counts for Beta 55:

TIME_TO_DOM_LOADING_MS = 20.62M (This count is very small!!)
TIME_TO_DOM_INTERACTIVE_MS = 6.27B
TIME_TO_DOM_CONTENT_LOADED_START_MS = 7.08B
TIME_TO_DOM_CONTENT_LOADED_END_MS = 7.08B (LOADED_END count is same as LOADED_START, as I would expect)
TIME_TO_NON_BLANK_PAINT_MS = 4.02B
TIME_TO_DOM_COMPLETE_MS = 5.31B

https://telemetry.mozilla.org/new-pipeline/dist.html#max_channel_version=beta%252F55&measure=TIME_TO_DOM_LOADING_MS

In bug 1344893 comment 38, Wei-Cheng said:

> I think that's because mTiming does not always ready when the document is in loading state.
> We probably need to record those probes in nsDocument::SetReadyStateInternal directly.

If mTiming is not always ready when we report the telemetry, we may be missing some important telemetry data. TIME_TO_DOM_LOADING_MS, in particular, has two orders of magnitude fewer samples than the other TIME_TO_DOM_*_MS probes.

Comment 1

[Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] (left Mozilla)]

Do you think we still need to collect data from parent process? AFAIK those data in parent process only represents XUL/background page's loading time.

Comment 2

[Chris Peterson [:cpeterson]]

(In reply to Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] from comment #1)
> Do you think we still need to collect data from parent process? AFAIK those
> data in parent process only represents XUL/background page's loading time.

I don't think we need to collect any TIME_TO_DOM_* data from the parent process. As you pointed out, the parent process only records XUL/background page loads and we mostly care about the load times for real web pages.

Comment 3

[Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] (left Mozilla)]

Attachment: Bug 1387625 - Fix TIME_TO_DOM_LOADING_MS record timing.

nsDocument::mTiming can be nullptr when the document is still loading, so we
should not record ready state probes in nsDOMNavigationTiming.

Review commit: https://reviewboard.mozilla.org/r/171524/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/171524/

Comment 4

[Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] (left Mozilla)]

Comment on attachment 8900130 [details]
Bug 1387625 - Fix TIME_TO_DOM_LOADING_MS record timing.

I need to change some parts.

Comment 5

[Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] (left Mozilla)]

Comment on attachment 8900130 [details]
Bug 1387625 - Fix TIME_TO_DOM_LOADING_MS record timing.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/171524/diff/1-2/

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

Remember that document.write usage after load event has fired may also disturb the metrics a bit.

Comment 7

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8900130 [details]
Bug 1387625 - Fix TIME_TO_DOM_LOADING_MS record timing.

https://reviewboard.mozilla.org/r/171524/#review177308

But I guess this is at least better what we have now.
I still wonder what we should do with document.open()/write()/close() case.

Comment 8

[Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] (left Mozilla)]

Comment on attachment 8900130 [details]
Bug 1387625 - Fix TIME_TO_DOM_LOADING_MS record timing.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/171524/diff/2-3/

Comment 9

[Wei-Cheng Pan [:wcpan] [:wcp] [:legnaleurc] (left Mozilla)]

Added flags to avoid interference from document.open()/write()/close().

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e40e343b7c37
Fix TIME_TO_DOM_LOADING_MS record timing. r=smaug

Comment 11

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

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

Comment 12

[Gerry Chang [:gchang]]

Too late for 56. Mass won't fix for 56.