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

Status: VERIFIED FIXED

(Toolkit :: Startup and Profile System, defect)

Description

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

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.

Comment 1

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

Might be related to bug 1690877.

Comment 2

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

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

Comment 3

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

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

Comment 4

[Dave Townsend [:mossop]]

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.

Comment 5

[Haik Aftandilian [:haik]]

@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.)

Comment 6

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

Attachment: 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?

Comment 7

[Julien Cristau [:jcristau]]

I'll track in bug 1690877.

Comment 8

[Haik Aftandilian [:haik]]

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

Comment 9

[Mathew Hodson]

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

Comment 10

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

Yes, and fixed.

Comment 11

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

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

Comment 12

[Jonathan Kew (:jfkthame)]

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

Comment 13

[Jonathan Kew (: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.

Comment 14

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

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)

Comment 15

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

[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

Comment 16

[Jonathan Kew (:jfkthame)]

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

Comment 17

[Jonathan Kew (:jfkthame)]

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.

Comment 18

[Jonathan Kew (:jfkthame)]

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.

Comment 19

[Jonathan Kew (:jfkthame)]

Attachment: Bug 1691719 - Don't explicitly activate supplemental fonts directory when building with pre-Catalina SDK, as the fonts are automatically made available. r=lsalzman

Comment 20

[Jonathan Kew (:jfkthame)]

Attachment: Bug 1691719 - Optimize InitSystemFontNames when running on Catalina or later, where the .SFNS is a variable font with optical sizing. r=lsalzman

Depends on D105042

Comment 21

[Pulsebot]

Pushed by [e-mail]:
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

Comment 22

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/366b4723b0a0
https://hg.mozilla.org/mozilla-central/rev/0935679e9bce

Comment 23

[Catalin Sasca, QA [:csasca]]

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.

Comment 24

[Henrik Skupin (:whimboo) [⌚️UTC+1]]

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