1661166 - Profiler shows really long "First Contentful Paint" bar, extending from pageload to print-preview's first rendering

Status: RESOLVED FIXED

(Core :: Print Preview, defect)

Description

[Daniel Holbert [:dholbert]]

STR:

1. Start with a fresh Firefox user-profile.
2. Visit https://profiler.firefox.com/ and click "Enable Profiler Menu Button"
3. Start profiling (Ctrl+Shift+1)
4. Load some simple site like https://example.org/
5. Wait a bit, and then do Ctrl+P
6. Capture the profile (Ctrl+Shift+2)
7. Show the content-process track for the site that you visited (e.g. example.org) - it might be hidden - and look at that track.

ACTUAL RESULTS:
There's a "Time to first contentful paint" black bar shown in the profile, from the time the page loaded to the time the print UI's print-preview rendering completed. This can span arbitrary amounts of time (and look like an arbitrarily large time-to-first-contentful-paint), since you can let an arbitrary amount of time pass between pageload and printing.

EXPECTED RESULTS:
No such bar. Or possibly: a bar from when you initiate the print operation (or when we clone the document for printing) to the first print-preview paint.

(Note: I'm assuming you have tab-modal printing enabled; it's enabled by default in Firefox Nightly right now via the pref print.tab_modal.enabled = true)

Comment 1

[Daniel Holbert [:dholbert]]

Here's a profile showing this issue:
https://share.firefox.dev/3hxlnWa

The page loaded between the profile's 1.2s - 1.4s timestamps (i.e. it took ~200ms or less to load). At around 3.3 seconds, I did Ctrl+P to print. At around 5.6 seconds, we showed the print UI. And there's a bogus "Time-to-first-contentful-paint" black bar that extends from pageload up until the print UI is shown.

(Side note: you may notice that the profile shows a long delay between Ctrl+P and the print UI coming up -- that's tracked in a separate bug, which is Bug 1661157)

Comment 2

[Daniel Holbert [:dholbert]]

Another profile, where I've waited a bit longer before initiating a print operation:
https://share.firefox.dev/2EhJda4

It shows a supposed 15.4s firstcontentfulpaint bar, but that's meaningless because it's mostly tracking how long I waited before printing.

Comment 3

[Markus Stange [:mstange]]

Sean, could you check whether we're accurately detecting the contentful paint here?

Comment 4

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

From your first profile, select the Web Content (3/3) track, go to the Marker Chart or Marker Table and filter on "firstcontent", you'll see two "FirstContentfulPaint" markers:

• from 1.147s, duration 158ms, which corresponds to your expectation, and we can see the screenshot with the example.com page becoming visible.
• also from 1.147s, but duration 4.4s, that's the troubling one, which shows as the long black bar ending when the print preview is visible.

In the code that generates these markers, the start timestamp is nsDOMNavigationTiming::mNavigationStart.
I'm guessing that the issue in your scenario, is that this navigation start should have been the time you pressed ctrl+P?
I would argue that this is more an issue about nsDOMNavigationTiming not keeping track of the new navigation happening with the print preview.

I'll redirect this bug to "Print Preview", hopefully people there will know better about this, and what should be done with the nsDOMNavigationTiming in that case.

Comment 5

[Hiroyuki Ikezoe (:hiro)]

(In reply to Gerald Squelart [:gerald] (he/him) from comment #4)

In the code that generates these markers, the start timestamp is nsDOMNavigationTiming::mNavigationStart.
I'm guessing that the issue in your scenario, is that this navigation start should have been the time you pressed ctrl+P?

No, the navigation timing for printing documents (i.e. cloned documents of the original ones) is same as the original ones. here is the relevant code. This is necessary to show animations properly in the cloned documents.

Comment 6

[Sean Feng [:sefeng]]

We only generate one contentful paint marker per document, I think this is the case in which printing creates a new/cloned document, and this is where the long-running contentful paint marker comes from.

I expect the fix should be not generating the paint markers for printing documents.

Comment 7

[Daniel Holbert [:dholbert]]

(In reply to Sean Feng [:sefeng] from comment #6)

We only generate one contentful paint marker per document, I think this is the case in which printing creates a new/cloned document, and this is where the long-running contentful paint marker comes from.

I expect the fix should be not generating the paint markers for printing documents.

That sounds fine to me. Thanks for looking into this!

Comment 8

[Sean Feng [:sefeng]]

I see there's another issue in our profiler is since the cloned document has the same URI as the original document, there's no way to tell if the marker is from the cloned document or the original document. I filed bug 1662246 for this.

Comment 9

[Sean Feng [:sefeng]]

Attachment: Bug 1661166 - Don't record paint timings if it is a print context r=mstange

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/cf65af7100e5
Don't record paint timings if it is a print context r=mstange

Comment 11

[Andreea Pavel [:apavel]]

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