firefox reloads every font.cache for every page loaded

RESOLVED FIXED in mozilla1.9.1b1

Status

()

Core
Graphics
--
major
RESOLVED FIXED
10 years ago
9 years ago

People

(Reporter: Paul Brannan, Assigned: karlt)

Tracking

({perf})

Trunk
mozilla1.9.1b1
x86
Linux
Points:
---
Dependency tree / graph
Bug Flags:
blocking1.9 -

Firefox Tracking Flags

(Not tracked)

Details

(URL)

Attachments

(1 attachment)

(Reporter)

Description

10 years ago
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
(Reporter)

Comment 1

10 years ago
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.

Updated

10 years ago
Component: General → GFX: Thebes
Keywords: perf
Product: Firefox → Core
QA Contact: general → thebes
Version: unspecified → Trunk

Updated

10 years ago
Severity: normal → major

Comment 2

10 years ago
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

10 years ago
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).
(Reporter)

Comment 4

10 years ago
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
(Assignee)

Updated

10 years ago
Status: UNCONFIRMED → NEW
Ever confirmed: true
Flags: blocking1.9?

Comment 5

10 years ago
Given the upgrade fixed the issue moving off our 1.9 blocker list
Flags: blocking1.9? → blocking1.9-
(Assignee)

Comment 6

10 years ago
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.
(Assignee)

Comment 7

10 years ago
(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.
Depends on: 401988, 414692

Comment 8

10 years ago
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
Flags: blocking1.9- → blocking1.9?
Marking blocking- based on comments; if there is new data to shows that this is an issue, please renominate.
Flags: blocking1.9? → blocking1.9-

Comment 10

9 years ago
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

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

Comment 12

9 years ago
The patch has been applied upstream, and is in fontconfig-2.6.0.
(Assignee)

Updated

9 years ago
Blocks: 448298
(Assignee)

Updated

9 years ago
Assignee: nobody → mozbugz
Blocks: 449356
Status: NEW → ASSIGNED
(Assignee)

Comment 13

9 years ago
Created attachment 338579 [details] [diff] [review]
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.
Attachment #338579 - Flags: review?(roc)
Does gfxGtkPlatform::UpdateFontList ever actually get called? I can't see how. If not, then we don't need this aForce parameter.
(Assignee)

Comment 15

9 years ago
(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
I think we should seriously consider removing that method. But anyway, I think probably Stuart or Vlad should review this.
Attachment #338579 - Flags: review?(roc) → review?(pavlov)

Updated

9 years ago
Attachment #338579 - Flags: review?(pavlov) → review+
(Assignee)

Updated

9 years ago
Status: ASSIGNED → RESOLVED
Last Resolved: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla1.9.1b1
(Assignee)

Comment 17

9 years ago
http://hg.mozilla.org/mozilla-central/rev/6b38ceafa9ad
(Assignee)

Comment 18

9 years ago
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
You need to log in before you can comment on or make changes to this bug.