1556568 - firstPaint metric is broken

Status: RESOLVED FIXED

(Core :: Web Painting, defect, P2)

Description

[Timothy Nikkel (:tnikkel)]

See Bug 1546140 comment 28 and Bug 1546140 comment 33.

Summary: we get telemetry pings from sessions that look completely normal that have very large firstPaint times in the tens of hours. They don't seem to be randomly corrupted data because they are always less than the session length. We get a completely usable browser from disabling the painting code at the firstPaint call site and this isn't all that surprising given how painting works.

Comment 1

[Timothy Nikkel (:tnikkel)]

Matt, 1) does my analysis make sense? 2) where/how should we measure first paint?

Comment 2

[Matt Woodrow (:mattwoodrow)]

I think it does! It's not surprising that we don't run the code in nsViewManager::Refresh very often.

It's not entirely clear what firstPaint wants to measure, but I think PresShell::Paint (or nsViewManager::ProcessPendingUpdatesPaint) is pretty similar to what we have.

Alternatively we could try to measure when we get notification that we've actually composited, but I'm not sure we need to.

Comment 3

[Timothy Nikkel (:tnikkel)]

(In reply to Matt Woodrow (:mattwoodrow) from comment #2)

It's not entirely clear what firstPaint wants to measure, but I think
PresShell::Paint (or nsViewManager::ProcessPendingUpdatesPaint) is pretty
similar to what we have.

Alternatively we could try to measure when we get notification that we've
actually composited, but I'm not sure we need to.

I think it is intended to record when we first paint something under "our" control (as opposed to an OS controlled background color or something) to the screen. So that would more closely correspond to the end of the first composite I think. Is there not likely to be much of a gap between PresShell::Paint and composite?

Comment 4

[Matt Woodrow (:mattwoodrow)]

I'd expect ~16ms difference, assuming that we managed to paint fast enough.

Comment 6

[Timothy Nikkel (:tnikkel)]

Have patch, just validating that I get expected results locally and on try server.

Comment 7

[Denis Palmeiro [:denispal]]

I don't think this needs any qf triaging. Looks like Timothy has this under control.

Comment 8

[Timothy Nikkel (:tnikkel)]

(In reply to Matt Woodrow (:mattwoodrow) from comment #4)

I'd expect ~16ms difference, assuming that we managed to paint fast enough.

I talked with Matt in person and convinced him we should measure after composite in case of a slow first composite.

Comment 9

[Timothy Nikkel (:tnikkel)]

Attachment: Bug 1556568. Fix the first paint telemetry metric.

Comment 10

[Timothy Nikkel (:tnikkel)]

Attachment: data collection review

Comment 11

[Chris H-C :chutten]

Comment on attachment 9082859 [details]
data collection review

DATA COLLECTION REVIEW RESPONSE:

    Is there or will there be documentation that describes the schema for the ultimate data set available publicly, complete and accurate?

Yes. This collection is Telemetry so is documented in its definitions file [Scalars.yaml](https://hg.mozilla.org/mozilla-central/file/tip/toolkit/components/telemetry/Scalars.yaml) and the [Probe Dictionary](https://telemetry.mozilla.org/probe-dictionary/).

    Is there a control mechanism that allows the user to turn the data collection on and off?

Yes. This collection is Telemetry so can be controlled through Firefox's Preferences.

    If the request is for permanent data collection, is there someone who will monitor the data over time?

Yes, Timothy Nikkel is responsible.

    Using the category system of data types on the Mozilla wiki, what collection type of data do the requested measurements fall under?

Category 1, Technical.

    Is the data collection request for default-on or default-off?

Default on for all channels.

    Does the instrumentation include the addition of any new identifiers?

No.

    Is the data collection covered by the existing Firefox privacy notice?

Yes.

    Does there need to be a check-in in the future to determine whether to renew the data?

No. This collection is permanent.

---
Result: datareview+

Comment 12

[Mike Conley (:mconley) (:⚙️)]

Hey tn, any updates on this patch?

Comment 13

[Timothy Nikkel (:tnikkel)]

I kind of lost steam on this, I hope to circle back to this though.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cf99b713375c
Fix the first paint telemetry metric. r=mattwoodrow,chutten

Comment 15

[Oana Pop-Rus]

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

Comment 16

[Timothy Nikkel (:tnikkel)]

Took a quick look at the first batch of telemetry for this: so far it looks exactly what we would expect, broadly similar to first paint but with a much smaller proportion of values in the largest bucket. Simple measures firstpaint has 11.86% in the > 30 seconds bucket, Simple measures firstpaint has 0.81% in the same bucket.

I'll also want to look at the number of sessions that report first_paint vs first_paint2 (many sessions don't report first_paint because it's never called). Hopefully almost all sessions report first_paint2. As well as just look at the raw values of the two variables for many sessions to see how they track each other.

Comment 17

[Timothy Nikkel (:tnikkel)]

Looks like the first paint two measures have about 3% more results.