Closed Bug 1661166 Opened 4 years ago Closed 4 years ago

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

Categories

(Core :: Print Preview, defect)

defect

Tracking

()

RESOLVED FIXED
82 Branch
Tracking Status
firefox82 --- fixed

People

(Reporter: dholbert, Assigned: sefeng)

Details

Attachments

(1 file)

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)

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)

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.

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

Flags: needinfo?(sefeng)

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.

Component: Gecko Profiler → Print Preview

(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.

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.

Assignee: nobody → sefeng
Flags: needinfo?(sefeng)

(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!

Status: NEW → ASSIGNED
Severity: -- → S3

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.

Pushed by sefeng@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/cf65af7100e5 Don't record paint timings if it is a print context r=mstange
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 82 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: