404857 - firefox reloads every font.cache for every page loaded

Status: RESOLVED FIXED

(Core :: Graphics, defect)

Description

[Paul Brannan]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9b1) Gecko/2007110903 Firefox/3.0b1
Build Identifier: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9b1) Gecko/2007110903 Firefox/3.0b1

I noticed today when trying out firefox 3.0b1 that it was unusably slow.  An strace revealed that pressing reload on google.com caused firefox to search through the font path and read each font.cache-1 files.  Pressing reload again causes the files to be read again.

This does not appear to happen on firefox 2.0.

Reproducible: Always

Steps to Reproduce:
1. Start firefox
2. Visit google.com
3. Run strace -p <pid>, where <pid> is the pid of firefox-bin
4. Press the reload button
5. Kill strace - you will see many open() calls for font files

Comment 1

[Paul Brannan]

Here's the strace output:

http://rubystuff.org/google.reload.txt

Note the number of font cache files read:

[pbrannan@zaphod pbrannan]$ grep ^open /tmp/google.reload.txt | grep fonts.cache-1 | wc -l
324

And the total number of font cache files on the machine:

[pbrannan@zaphod pbrannan]$ locate fonts.cache-1 | wc -l
25

I should also mention that I'm running on SuSE 9.1.  I have not tested this on a newer revision of the OS.

Comment 2

[Sylvain Pasche]

I tried running with "strace -e trace=file" to show only the i/o system calls on Ubuntu 7.10 x86_64. I'm not seeing lots of fonts.cache accesses, however I can see that every time I reload a page the fontconfig fonts directories are scanned. Which shows me something like:

[...]
[pid 30867] stat("/usr/share/fonts/X11/misc", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
[pid 30867] stat("/usr/share/fonts/X11/util", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 30867] stat("/usr/share/fonts/truetype/arphic", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 30867] stat("/usr/share/fonts/truetype/freefont", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 30867] stat("/usr/share/fonts/truetype/kochi", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 30867] stat("/usr/share/fonts/truetype/msttcorefonts", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 30867] stat("/usr/share/fonts/truetype/openoffice", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid 30867] stat("/usr/share/fonts/truetype/thai", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[...]

Those access() calls should be rather cheap, but there may be something wrong happening here.

Comment 3

[Peter Weilbacher]

The function that would do that is in gfxFontconfigUtils::UpdateFontListInternal. There it calls Fontconfig to do FcConfigUptoDate which according to the man-page (or http://www.fontconfig.org/fontconfig-devel/r1768.html) does a stat on every one of its config and probably cache files. Bug unless you have a daemon running on your system that updates the timestamps on those files all the time, it should not re-open them, and so it should be really fast.

Perhaps Fontconfig on SuSE 9.1 was broken in some way? Btw, I noticed no open() calls at all during the experiment (just tons of stat calls) when attaching strace to the running program and reloading Google a couple of times (Gentoo Linux with Fontconfig 2.4.2).

Comment 4

[Paul Brannan]

Upgraded from fontconfig 2.2.92.20040221 (which came with SuSE 9.1)  to 2.2.99.20050218 (which came with SuSE 9.3).  This seems to have corrected the problem with open(); it is not called at all during a reload anymore.  Reloading a webpage is significantly faster now.

However, it still seems silly to re-stat all the font directories multiple times when reloading a webpage:

[pbrannan@zaphod pbrannan]$ grep stat64 /tmp/asdf | grep fonts.conf
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
stat64("/etc/fonts/fonts.conf", {st_mode=S_IFREG|0644, st_size=13675, ...}) = 0
[pbrannan@zaphod pbrannan]$ grep stat64 /tmp/asdf | grep fonts.conf | wc -l
20

Comment 5

[Mike Schroepfer]

Given the upgrade fixed the issue moving off our 1.9 blocker list

Comment 6

[Karl Tomlinson (:karlt)]

We still shouldn't need to re-stat multiple files in each page load.
But I don't know the effect on performance, so we haven't got enough data yet to suggest that this should be a blocker.

Comment 7

[Karl Tomlinson (:karlt)]

(In reply to comment #3)
> The function that would do that is in
> gfxFontconfigUtils::UpdateFontListInternal. There it calls Fontconfig to do
> FcConfigUptoDate which according to the man-page (or
> http://www.fontconfig.org/fontconfig-devel/r1768.html) does a stat on every
> one of its config and probably cache files. 

The changes in bug 401988 mean that this code path is now not being hit for general text rendering, and avoiding this may have contributed to much of the 6% Tp2 improvement.

The code path is still used in MathML font selection for operators.

Comment 8

[Marco Pesenti Gritti]

We have been seeing this issue with fontconfig 2.4.2. I suspect it might have been fixed for Paul just because upgrading the rpm regenerated the caches.

For reference:
http://dev.laptop.org/ticket/6046

Comment 9

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Marking blocking- based on comments; if there is new data to shows that this is an issue, please renominate.

Comment 10

[Sayamindu Dasgupta]

We found it to be caused by fontconfig being unable to handle future timestamps properly. Some of the font dirs had their timestamps in the future, causing FcConfigUptoDate() to return FcFalse each and every time (http://dev.laptop.org/ticket/6046#comment:27). 
We have a patch against fontconfig, and the initial results suggests that it fixes the issue.

Comment 11

[timeless]

the upstream bug is https://bugs.freedesktop.org/show_bug.cgi?id=14424 and has no traction

Comment 12

[Sayamindu Dasgupta]

The patch has been applied upstream, and is in fontconfig-2.6.0.

Comment 13

[Karl Tomlinson (:karlt)]

Attachment: use FcInitBringUptoDate()

This resolves the remaining issue (comment 4).

FcInitBringUptoDate() only rescans at intervals determined by the <rescan>
fontconfig setting.  The interval may be configured by the user but is
typically 30 seconds.

Also, fontconfig may update its current config in a call to FcFontSetList,
which would mean that FcConfigUptoDate would not know that the change has
happened.  The best way to detect an update seems to be to compare the results
of FcConfigGetCurrent().  FcInitReinitialize() creates a new config before
destroying the old config, so the only way that we'd miss an update is if
fontconfig did more than one update and the memory for the most recent config
happened to be at the same location as the original config.  (FcConfigs are
not reference counted so we can't force the original config to stay alive).

UpdateFontListInternal is called at all public access points to the
gfxFontconfigUtils object so there is no need to call it from the constructor.

Comment 14

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Does gfxGtkPlatform::UpdateFontList ever actually get called? I can't see how. If not, then we don't need this aForce parameter.

Comment 15

[Karl Tomlinson (:karlt)]

(In reply to comment #14)
I don't think there are any current callers, but there is a public API:

http://hg.mozilla.org/mozilla-central/annotate/19030b97ca13/gfx/idl/nsIFontEnumerator.idl#l81

The return value will be wrong though:

http://hg.mozilla.org/mozilla-central/annotate/1aecd2a9914d/gfx/src/thebes/nsThebesFontEnumerator.cpp#l128

Comment 16

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I think we should seriously consider removing that method. But anyway, I think probably Stuart or Vlad should review this.

Comment 17

[Karl Tomlinson (:karlt)]

http://hg.mozilla.org/mozilla-central/rev/6b38ceafa9ad

Comment 18

[Karl Tomlinson (:karlt)]

This saved about 100ms (6-7%) on startup time:

http://graphs.mozilla.org/graph.html#show=395164,395123,395133,911692,1431030&sel=1222007053,1222050589

http://hg.mozilla.org/mozilla-central/pushloghtml?startdate=September+21+2008+12%3A00&enddate=September+21+2008+15%3A00