Bug 180979 – Web Inspector: Slow open time enumerating system fonts (FontCache::systemFontFamilies)

• Component: Web Inspector
• Status: RESOLVED FIXED

[Chris Chiera]

This issue has been ongoing for a long time. 

Issue: When opening "any" website, then when opening Web Inspector, the HTML/CSS content doesn't load for several seconds. http://share.heavymark.com/330l1o0i3v2q If I leave the inspector open and navigate to other pages, those pages inspector content load instantly. After the initial slow load, if I close just the inspector and reopen the inspector on the same page it loads instantly. If I do that and refresh the page it also loads instantly. If close the insector and go to another website in the same window the slow inspector load issue occurs.

- This happens the exact same whether Safari, Safari Preview or Webkit. Does not happen in any version of Chrome.
- This happens in High Sierra, also happened in Sierra, can't recall if happened before then.
- This happens on all of my new Macs and old and even when using Guest Account on anyone else's computer.
- This happens when visiting any website, even local html files on my computer.
- Have Gbps speeds here, ethernet, but also can replicate on any other network.
- Happens whether normal window, or empty cache, or incongnito mode, or all extensions disabled.

The common thread however is my iCloud account. For instance, I can buy a new Mac, or you could create a guest account on your Mac, and if I don't enter my iCloud credentials Inspector will load perfectly. Once I enter my Apple ID/iCloud on any computer and after it's finished syncing completely the issue returns without fail. On comptuers such as my new iMac 5K with 64GB connected to 1gbps the lag is about 5 seconds (but that's each and everytime I reopen inspector on a website so adds up, but the delay is slightly longer on say my Macbook when at a coffee shop with 8GB. 

Creating a new AppleID is not an option. And there appears to be no way to reset any/all settings related to Safari iCloud. I tried looking into Console when it happenes but wasn't able to determine the issue as well anything else I could think of, including enabling Debug menu in Safari.

While this affects Web Inspector where it does appear specific to my iCloud account not sure if anyone knows who is the best person to resolve this who would be able to somehow remove whatever corruption/settings that keep getting synced with any new computer that cause this issue with my iCloud account. Or if there is a fix for Webkit that could help somehow. Thank you for your time.

[Joseph Pecoraro]

Nothing in Web Inspector is tied to an iCloud account. However if you feel this really is related to your iCloud account I would recommend filing a bug report with Apple <https://bugreport.apple.com> (starting in a Safari component would be fine, include the video you included here as a `sudo sysdiagnose` to gather any relevant logs.

The video shows that Web Inspector itself loads slowly (you selected Inspect Element, and Safari showed Web Inspector on the Console tab quickly but took multiple seconds to actually switch to the Elements tab and be usable). This seems to be some kind of performance issue. It could even be another process hogging CPU time.

If you can readily reproduce this issue, try to run a `sudo spindump` immediately after opening Web Inspector. That would give a little information about what the entire system is doing, and if another process is consuming CPU time / inspector process is getting no CPU time.

If you do file a radar (which I recommend as the best path forward), please add a comment here with the bug number (the radar number) so I can view it. You can then upload attachments like the sysdiagnose / spindump to the radar to keep them private.

---

As a potential workaround you can try starting Web Inspector with no settings at all.

Note these steps are specific to the system Safari, not Safari Technology Preview.

  1. Quit Safari
  2. Move aside local settings into a temporary directory so it starts fresh
  $ mkdir -p ~/Desktop/temp
  $ mv ~/Library/WebKit/com.apple.Safari/WebsiteData/LocalStorage/file__0.localstorage* ~/Desktop/temp
  3. Restart Safari
    => See if the issue reproduces

If you want to restore your web inspector / file local settings you can move them back:

  1. Quit Safari
  2. Move files back (replacing the new ones that might have just been created)
  $ mv ~/Desktop/temp/file__0.localstorage* ~/Library/WebKit/com.apple.Safari/WebsiteData/LocalStorage
  3. Restart Safari
    => Should have your Web Inspector settings back

If it turns out that these settings were causing the problem it would be great if you could attach the file__0.localstorage to the radar so that we can investigate how those would affect performance here.

[Chris Chiera]

Thanks for providing such a detailed and thoughtful response.

From my testing it definitely is related to iCloud syncing, in that, if you created a Guest account on your computer and entered my iCloud login for instance you'd be able to replicate the issue. However, it could perhaps be that iCloud is syncing something seemingly unrelated to Safari, that is however indirectly causing the Web Inspector slow load time. I can replicate it on a brand new computer, fresh install without changing any settings or installing any new apps, other than entering my iCloud info during setep. It doesn't happen immediately but does eventually once iCloud has finished syncing. I tried reformatting one computer and not entering iCloud during setup, then under iCloud syncing I unchecked everything and slowly started checking things to try to isolate issue but wasnt unable to determine which particular iCloud sync caused the issue.

I went ahead and tried moving the local storage files for Safari, but didn't change anything, but that was a good idea to test.

I filed a Bug report back in 2016, but I may not have filed in in the appropriate category and also hadn't done all the testing to isolate the issue at that time, so I'll file one now accordingly. To note, it looks like the issue started when upgrading to the first Sierra beta(s) back in 2016.

In that video example, it started in console which was a bit unusual, but most all times it starts in Elements and takes 5+ seconds to load there. Just did another video here: http://share.heavymark.com/0y3G171X2Q2m 

I replicated the issue then ran "sudo sysdiagnose" and have included that in the Apple bug report. Also attached spindump there which I ran immediately after opening inspector in Safari. Happy to provide any additional details here or there. Thanks once again for all your help already.

[Chris Chiera]

Forgot to add that the Apple Bug Report radar number is: 36146670

[Joseph Pecoraro]

Thanks for the spindump. It produced some very useful information. The radar doesn't appear to have a sysdiagnose attached, maybe it failed to attached?

The spindump shows nearly 100% of the samples in the inspected page's process (2 seconds of CPU time) was enumerating the system fonts.

> Process:         com.apple.WebKit.WebContent [24549]
> Responsible:     Safari [24486]
> CPU Time:        3.874s
> ...
>   Thread           DispatchQueue 1           1000 samples (1-1000)     priority 38-46 (base 46)  cpu time 3.819s
>    ...
>     419  Inspector::BackendDispatcher::dispatch(WTF::String const&) + 2330 (JavaScriptCore + 7255306) [0x7fff4a87c50a]
>       418  Inspector::CSSBackendDispatcher::dispatch(long, WTF::String const&, WTF::Ref<Inspector::InspectorObject>&&) + 570 (JavaScriptCore + 7272730) [0x7fff4a88091a]
>         418  Inspector::CSSBackendDispatcher::getSupportedSystemFontFamilyNames(long, WTF::RefPtr<Inspector::InspectorObject>&&) + 96 (JavaScriptCore + 7283136) [0x7fff4a8831c0]
>           418  WebCore::InspectorCSSAgent::getSupportedSystemFontFamilyNames(WTF::String&, WTF::RefPtr<Inspector::Protocol::Array<WTF::String> >&) + 69 (WebCore + 7807109) [0x7fff54909085]
>             418  WebCore::FontCache::systemFontFamilies() + 79 (WebCore + 5651663) [0x7fff546faccf]
>               418  CTFontDescriptorCreateMatchingFontDescriptors ...
>                 ...

This amount of time is unexpectedly long, and would certainly block other messages the inspector (and even the page) need to remain responsive.

Do you happen to have a lot of custom fonts installed?

[Joseph Pecoraro]

One thing Web Inspector can do is to defer loading the system fonts closer to when it is actually needed. Currently this is done immediately on opening Web Inspector.

[Chris Chiera]

You are my hero, and clearly Christmas has come early this year. Your suspicions on fonts immediately rang promising, since I do have a couple font collections such as Adobe and Google fonts which total about 800 custom which I sync via iCloud.

Backed up the fonts, then deleted them all from Fonts on one computer and all Safari browsers are loading Inspector instantly again!

I never considered the number of fonts an issue as I use them extensively for graphic design and have never ran into an issue that I know of because of the number other than it seems with Web Inspector. 

I did see the font folder had about 3K, so assuming the 800 font families and perhaps 3L were the number of actual font files, Also perhaps some were corrupted or some other similar issue that's causing the Inspector issue. So I can slowly readd the fonts and see if I can determine how many or which specifically cause the issue.

That being said, I believe I've always had roughly the same number of fonts since the issue started which I believe was when Sierra beta's first came out, so not sure if something changed at that point to in MacOS or Safari that brought the issue to light. Also Chrome Inspector has always opened instantly even with all my fonts installed and enabled. So would be interesting to see how they deal with fonts, and if perhaps they delay loading them as you suggested.

Wasn't sure if I could attach that syslog to the radar so I included a link to the file, but if that didn't come through I can try uploading directly this morning to the radar.

Thank you so much Joseph, you are amazing!

[Joseph Pecoraro]

> Backed up the fonts, then deleted them all from Fonts on one computer and
> all Safari browsers are loading Inspector instantly again!

Excellent! So this was indeed the issue.


> That being said, I believe I've always had roughly the same number of fonts
> since the issue started which I believe was when Sierra beta's first came
> out, so not sure if something changed at that point to in MacOS or Safari
> that brought the issue to light.

Correct, WebKit's Web Inspector first started getting a list of all fonts some time in Sierra, so that would be the reason this started happening then.


> Also Chrome Inspector has always opened instantly even with all my fonts
> installed and enabled. So would be interesting to see how they deal with
> fonts, and if perhaps they delay loading them as you suggested.

Chrome Dev Tools do not auto complete system font names anywhere, so I don't think they do anything equivalent to what WebKit is doing.


> Thank you so much Joseph, you are amazing!

Sure! We will try to improve this to ensure a great experience regardless of how many fonts are on someone's system.

[Joseph Pecoraro]

Created attachment 330336 [details]
[BENCHMARK] Program that can be used to benchmark and compare font family enumeration implementations

We can improve FontCache::systemFontFamilies. It was implemented using slow functions that were available on both macOS and iOS, but now that both platforms have CTFontManagerCopyAvailableFontFamilyNames it can be implemented in terms of that and be far more efficient.

Attached a test program that compares the before and after implementations.

  # Use CTFontDescriptorCreateMatchingFontDescriptors
  $ ./a.out

  # Use CTFontManagerCopyAvailableFontFamilyNames
  $ ./a.out new

On my system we can go from 379ms to 13ms and find 11 more fonts (and those new values work in a quick test):

> Current Version: 182 fonts
> Time: 378.215668ms
> Time: 380.014587ms
> Time: 377.239014ms
> Time: 382.326111ms
> Average: 379.448845
> 
> New Version: 193 fonts
> Time: 13.489217ms
> Time: 13.597557ms
> Time: 12.925188ms
> Time: 13.309677ms
> Average: 13.33040975
> 
> Difference: (New version finds more, no old values are missing)

Given this was used by Web Inspector only this seems like it would be a big win for opening web inspector.

I'll need to quickly check iOS.

[Joseph Pecoraro]

There is a speedup, but it is not as pronounced on iOS. However it does find about a hundred more fonts and it is using public API, so it seems worthwhile!

[Joseph Pecoraro]

<rdar://problem/36146670>

[Joseph Pecoraro]

Created attachment 330339 [details]
[PATCH] Proposed Fix

[Matt Baker]

Comment on attachment 330339 [details]
[PATCH] Proposed Fix

r=me, nice work!

[Matt Baker]

(In reply to Joseph Pecoraro from comment #5)
> One thing Web Inspector can do is to defer loading the system fonts closer
> to when it is actually needed. Currently this is done immediately on opening
> Web Inspector.

Should we bother with this enhancement? Sounds like the speedup is so great that there is no need.

[Devin Rousso]

Comment on attachment 330339 [details]
[PATCH] Proposed Fix

View in context: https://bugs.webkit.org/attachment.cgi?id=330339&action=review

> Source/WebCore/platform/graphics/cocoa/FontCacheCoreText.cpp:747
> +        // We don't want to make the hidden system fonts visible and since they
> +        // all begin with a period, ignore all fonts that begin with a period.
> +        if (CFStringHasPrefix(fontName, CFSTR(".")))

It appears that there is already a static function `fontIsSystemFont`, but it expects a `CTFontRef`.  Perhaps you can overload it with a version for `CFStringRef` and use it here instead of duplicating that logic.

[EWS Watchlist]

Comment on attachment 330339 [details]
[PATCH] Proposed Fix

Attachment 330339 [details] did not pass ios-sim-ews (ios-simulator-wk2):
Output: http://webkit-queues.webkit.org/results/5896799

New failing tests:
imported/w3c/web-platform-tests/service-workers/service-worker/update-after-navigation-fetch-event.https.html
fast/text/combining-character-sequence-fallback-crash.html

[EWS Watchlist]

Created attachment 330351 [details]
Archive of layout-test-results from ews125 for ios-simulator-wk2

The attached test failures were seen while running run-webkit-tests on the ios-sim-ews.
Bot: ews125  Port: ios-simulator-wk2  Platform: Mac OS X 10.12.6

[Joseph Pecoraro]

(In reply to Matt Baker from comment #13)
> (In reply to Joseph Pecoraro from comment #5)
> > One thing Web Inspector can do is to defer loading the system fonts closer
> > to when it is actually needed. Currently this is done immediately on opening
> > Web Inspector.
> 
> Should we bother with this enhancement? Sounds like the speedup is so great
> that there is no need.

On the iOS device I tested this still took >100ms. So we should consider it, but lets keep an eye on that. I don't think fonts can added to / modified iOS like they can on macOS, so it isn't as much of a concern. But I still think we can probably tweak this to defer some work during opening to a slightly better time.

[Joseph Pecoraro]

(In reply to Devin Rousso from comment #14)
> Comment on attachment 330339 [details]
> [PATCH] Proposed Fix
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=330339&action=review
> 
> > Source/WebCore/platform/graphics/cocoa/FontCacheCoreText.cpp:747
> > +        // We don't want to make the hidden system fonts visible and since they
> > +        // all begin with a period, ignore all fonts that begin with a period.
> > +        if (CFStringHasPrefix(fontName, CFSTR(".")))
> 
> It appears that there is already a static function `fontIsSystemFont`, but
> it expects a `CTFontRef`.  Perhaps you can overload it with a version for
> `CFStringRef` and use it here instead of duplicating that logic.

Great idea. I added:

    static inline bool fontNameIsSystemFont(CFStringRef fontName)
    {
        return CFStringGetLength(fontName) > 0 && CFStringGetCharacterAtIndex(fontName, 0) == '.';
    }

And used it where appropriate.

[Joseph Pecoraro]

Created attachment 330357 [details]
[PATCH] For Landing

I'll let the bots run this one more time.

[Joseph Pecoraro]

<https://trac.webkit.org/r226352>

[Ryan Haddad]

This change broke pre-High Sierra macOS builds:

/Volumes/Data/slave/elcapitan-release/build/Source/WebCore/platform/graphics/cocoa/FontCacheCoreText.cpp:751:13: error: use of undeclared identifier 'fontNameIsSystemFont'

https://build.webkit.org/builders/Apple%20El%20Capitan%20Release%20%28Build%29/builds/7658

[Ryan Haddad]

Rolled out in https://trac.webkit.org/r226359

It looks like fontNameIsSystemFont was defined inside a '#if ENABLE(VARIATION_FONTS)' block, but used outside of it. Mac EWS caught the failure before the patch was landed.

[Joseph Pecoraro]

(In reply to Ryan Haddad from comment #22)
> Rolled out in https://trac.webkit.org/r226359
> 
> It looks like fontNameIsSystemFont was defined inside a '#if
> ENABLE(VARIATION_FONTS)' block, but used outside of it. Mac EWS caught the
> failure before the patch was landed.

Grrr, I spent 5 minutes going through each of the EWS bubbles and I couldn't find that. Evidently the with UnifiedSources my strategy for finding the error messages no longer works. New approach will be to search for "error:".

[Joseph Pecoraro]

Created attachment 330401 [details]
[PATCH] For Bots 2

[WebKit Commit Bot]

Comment on attachment 330401 [details]
[PATCH] For Bots 2

Clearing flags on attachment: 330401

Committed r226371: <https://trac.webkit.org/changeset/226371>