Closed Bug 1691719 Opened 2 months ago Closed 2 months ago

550ms startup delay in gfxPlatformMac::CreatePlatformFontList on Big Sur

Categories

(Toolkit :: Startup and Profile System, defect)

Firefox 87
All
macOS
defect

Tracking

()

VERIFIED FIXED
87 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox85 --- unaffected
firefox86 --- unaffected
firefox87 + verified

People

(Reporter: whimboo, Assigned: jfkthame)

References

(Regression)

Details

(Keywords: perf, regression, Whiteboard: [qf])

Attachments

(3 files)

Mozilla/5.0 (Macintosh; Intel Mac OS X 10.16; rv:87.0) Gecko/20100101 Firefox/87.0 ID:20210208092848

Today I noticed a 550ms delay during the startup of Firefox and all the time is spent in gfxPlatformMac::CreatePlatformFontList.

Here the appropriate profile:
https://share.firefox.dev/3q55OJu

Jonathan mentioned that this could be a regression from bug 1687622. I will have a look and will compare the profiles from before and after.

OS: Unspecified → macOS
Hardware: Unspecified → All
Summary: 550ms startup delay in gfxPlatformMac::CreatePlatformFontList → 550ms startup delay in gfxPlatformMac::CreatePlatformFontList on Big Sur

Might be related to bug 1690877.

See Also: → 1690877

This is a regression and has been caused by bug 1687622.

Keywords: regression
Regressions: 1687622
Keywords: perf
Whiteboard: [qf]
Flags: needinfo?(jfkthame)

[Tracking Requested - why for this release]: Severe startup delay regression happening each time starting Firefox 87.

Given these are both pauses in bug CreatePlatformFontList I'm going to propose that these are just dupes, we an re-open this if the work there doesn't resolve it.

Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → DUPLICATE
Duplicate of bug: 1690877

@Henrik, could you attach the output of system_profiler SPFontsDataType to the bug so we can see your font list. (Assuming you are OK with sharing this information.)

No worries. Here the list of fonts on my system. Please note that I haven't installed any custom font, but upgraded my system each time. So maybe it's some old font causing problems?

Flags: needinfo?(haftandilian)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #6)

Created attachment 9202071 [details]
system_profiler SPFontsDataType output

No worries. Here the list of fonts on my system. Please note that I haven't installed any custom font, but upgraded my system each time. So maybe it's some old font causing problems?

Thanks. I can now reproduce on macOS 11 (aka 10.16) using MOZ_PROFILER_STARTUP=1 and I have the same configuration with respect to fonts. It might be that content processes started later don't hit this problem.

Flags: needinfo?(haftandilian)

I think you meant to set Regressed By 1687622 instead of the other way around.

Flags: needinfo?(hskupin)

Yes, and fixed.

Flags: needinfo?(hskupin)
Regressed by: 1687622
No longer regressions: 1687622

Bug 1690877 was fixed 2 days ago, but with my build containing this fix the 500ms startup delay is still present. As such reopening the bug.

Here a profile as created with firefox -screenshot a.png about:blank -profile xyz (already existing profile): https://share.firefox.dev/3aWkHHL

Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---

The patch in bug 1690877 should have essentially eliminated this issue in content processes, as they no longer call ActivateFontsFromDir on the Supplemental fonts directory. But we still do that in the parent; I don't see how we can avoid that without regressing behavior for the languages/scripts that are supported by those "supplemental" fonts on macOS.

Prior to bug 1687622, we simply failed to activate those fonts, and so those languages would've been unsupported unless the user happened to have installed additional fonts to cover them. We originally enabled support for those fonts back in bug 1392659, which probably added a comparable amount to startup time -- somewhat less, maybe, as there weren't as many fonts shipped back then -- but that's an unavoidable cost of the added functionality. This broke when Apple moved the location of the "language support" fonts. That presumably gave us a "free" but spurious startup-time improvement, as we no longer found the fonts; bug 1687622 just reinstated the functionality that had been lost across an OS update, and in the process we lose that "improvement" again.

There are a couple things we can probably do to help. According to the comment at https://searchfox.org/mozilla-central/rev/8d9564059dbc1e36fb9152e6b6227343d0b49662/gfx/thebes/gfxMacPlatformFontList.mm#813-816, we may not actually need to make this activation call as long as we're building with a pre-10.15 SDK. That would be the biggest win here, but it's likely to be temporary; at some point we'll want to update the SDK used (presumably we already must be using a newer SDK to build for the M1), and at that point it'll return.

We can also try eliminating the second call to [NSFont systemFontOfSize:] in InitSystemFontNames when running on Catalina or later, as we know that they use an optically-sized system font rather than separate Text and Display faces. I suspect this won't gain more than a few ms, though, as the font registry will probably have done all the hard work and cached the info it needs during the first call.

(Eventually we may be able to eliminate InitSystemFontNames altogether, by reimplementing the macOS font backend to use new APIs like CTFontCreateUIFontForLanguage to instantiate system fonts, instead of treating them as part of the main font list. This would potentially allow us to solve things like bug 1605605. But it'll be a pretty invasive bit of surgery, not to be undertaken lightly.)

Flags: needinfo?(jfkthame)

Try build with the patches suggested in comment 12, for testing: https://treeherder.mozilla.org/jobs?repo=try&revision=2e91652be41e9b3017cb88f985ec1ca69298e236

Assuming this helps with the issue here, we'll need to get QA to verify this doesn't regress anything else (e.g. bug 1687622) across a variety of macOS versions, but I'm hopeful that it'll be OK.

That looks way better now. The time we spend in this method is around 45ms now. Is that an appropriate number? Not sure what we had before. Is that something I can test on Big Sur, and if yes which version of Firefox?

Here the profile: https://share.firefox.dev/3b5mCtI (some parts cannot be symbolicated)

[Tracking Requested - why for this release]: Asking for tracking because it adds an additional 550ms delay during each startup of Firefox.

I tested with DevEdition and indeed 86 isn't affected because it doesn't have the fix from bug 1687622.

Here the profile: https://share.firefox.dev/3rLHBs3

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #14)

That looks way better now. The time we spend in this method is around 45ms now. Is that an appropriate number? Not sure what we had before. Is that something I can test on Big Sur, and if yes which version of Firefox?

Here the profile: https://share.firefox.dev/3b5mCtI (some parts cannot be symbolicated)

45ms sounds fine; most of that is spent just calling CTFontManagerCopyAvailableFontFamilyNames, which is out of our hands anyhow.

(Not sure why that profile is so lacking in symbols: I can't see any gfxPlatform*-related stuff at all, which makes it kinda unhelpful.)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #15)

I tested with DevEdition and indeed 86 isn't affected because it doesn't have the fix from bug 1687622.

Here the profile: https://share.firefox.dev/3rLHBs3

Note that this appears to be running with gfx.e10s.font-list.shared disabled (it's currently on by default for Nightly/Early Beta), so it's not entirely comparable, although this particular bit of initialization should be pretty much unaffected. In content processes it'd be quite different, though.

So before we try landing these patches, I'd like to ask QA to test the try build from https://treeherder.mozilla.org/jobs?repo=try&revision=2e91652be41e9b3017cb88f985ec1ca69298e236 and confirm whether it regresses bug 1687622 on macOS 10.14 or 10.15, as I don't have access to those systems to check it directly.

Catalin, you originally filed bug 1687622; could you please test the build from https://treeherder.mozilla.org/jobs?repo=try&revision=2e91652be41e9b3017cb88f985ec1ca69298e236 and check if it regresses that issue? I don't have a machine running 10.15 here to confirm it myself.

Flags: needinfo?(catalin.sasca)
Assignee: nobody → jfkthame
Pushed by jkew@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/366b4723b0a0
Don't explicitly activate supplemental fonts directory when building with pre-Catalina SDK, as the fonts are automatically made available. r=lsalzman
https://hg.mozilla.org/integration/autoland/rev/0935679e9bce
Optimize InitSystemFontNames when running on Catalina or later, where the .SFNS is a variable font with optical sizing. r=lsalzman
Status: REOPENED → RESOLVED
Closed: 2 months ago2 months ago
Resolution: --- → FIXED
Target Milestone: --- → 87 Branch

Hi Jonathan, just tried the build you linked in Comment 18 on macOS 10.15.7 and it doesn't seem to regress bug 1687622. Let me know if there is anything else that I can help with.

Flags: needinfo?(catalin.sasca)

Thanks for the fix. A newly generated profile no longer shows the 550ms delay.

You need to log in before you can comment on or make changes to this bug.