Bug 94427

Summary: Performance regression in git compared 2.11
Product: fontconfig Reporter: Antonio Orefice <kokoko3k>
Component: libraryAssignee: Akira TAGOH <akira>
Status: RESOLVED FIXED QA Contact: Behdad Esfahbod <freedesktop>
Severity: normal    
Priority: medium CC: akira, ebiggers3, fontconfig-bugs, fontconfigbugs
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: grep ^stat64 /tmp/out_fast|grep font >/tmp/stat_fast.txt
grep ^stat64 /tmp/out_slow|grep font >/tmp/stat_slow.txt
complete strace fast
complete strace slow

Description Antonio Orefice 2016-03-07 16:04:25 UTC
Created attachment 122139 [details]
grep ^stat64 /tmp/out_fast|grep font >/tmp/stat_fast.txt

On a not so powerfull ATOM 330 running at 2ghz, i've noticed that even the simplest gui application using qt4 or gtk2 toolkits (didn't test other) suffers from a high delay when starting up.
On this particular machine, i measured it to be around one second.


The following script /tmp/startuptime.sh 
measures the application startup time of the program "gtk-demo"
#---------------------------------------------------------------------
#!/bin/bash
ln -s /usr/bin/sleep /tmp/mysleep &>/dev/null
time /tmp/mysleep 999 &

gtk-demo &
while true ; do
    wmctrl -l|grep 'GTK+ Code Demos' &>/tmp/out
    if [ $? -eq 0 ] ; then
        killall mysleep &>/tmp/out
        break
    fi
    sleep 0.05
done
killall gtk-demo &>/tmp/out
unlink /tmp/mysleep
#---------------------------------------------------------------------



Test startup time with fontconfig and freetype from git:
#---------------------------------------------------------------------
$ /tmp/startuptime.sh
/tmp/startuptime.sh: riga 3:  4321 Terminato               /tmp/mysleep 999

real    0m1.149s
user    0m0.000s
sys     0m0.000s
#---------------------------------------------------------------------



Now with standard fontconfig and freetype:
#---------------------------------------------------------------------
$ /tmp/startuptime.sh
/tmp/startuptime.sh: riga 3:  4508 Terminato               /tmp/mysleep 999

real    0m0.325s
user    0m0.000s
sys     0m0.000s
#---------------------------------------------------------------------



If i isolate just use fontconfig from git, and freetype stable:
#---------------------------------------------------------------------
$ pacman -Q|grep 'fontconfig\|freetype2'
fontconfig 2.11.1-2
freetype2-infinality-ultimate 2.6.2-4

$ /tmp/startuptime.sh
/tmp/startuptime.sh: riga 3:  5692 Terminato               /tmp/mysleep 999

real    0m0.386s
user    0m0.000s
sys     0m0.000s
#---------------------------------------------------------------------




So it seems fontconfig is doing a lot of work with the ultimate patches.
This happens with regular user account, never-used user accounts and the root account too.
I've already tried to rebuild the font cache with fc-cache -f and ran it with root and regular user, without success...

i used strace to debug the issue (strace -f gtk-demo)
and created two files: out_slow and out_fast:

$ grep ^stat64 /tmp/out_slow|grep font|wc -l
4600

$ grep ^stat64 /tmp/out_fast|grep font|wc -l
47

In out_slow, you see, it seems to walk across all of the fonts and more:

grep ^stat64 /tmp/out_fast|grep font >/tmp/stat_fast.txt
http://pastebin.com/vBLXakzT

grep ^stat64 /tmp/out_slow|grep font >/tmp/stat_slow.txt
http://pastebin.com/f8KGrFGr

complete strace fast
http://pastebin.com/60RsQpy2

complete strace slow (had to split these because they were too big)
http://pastebin.com/fbXDFN2B
http://pastebin.com/We6SxwN0

I cant undesrtand if this is a bug or just the expected behaviour.
Comment 1 Antonio Orefice 2016-03-07 16:05:16 UTC
Created attachment 122140 [details]
grep ^stat64 /tmp/out_slow|grep font >/tmp/stat_slow.txt
Comment 2 Antonio Orefice 2016-03-07 16:06:08 UTC
Created attachment 122141 [details]
complete strace fast
Comment 3 Antonio Orefice 2016-03-07 16:07:18 UTC
Created attachment 122142 [details]
complete strace slow
Comment 4 Antonio Orefice 2016-03-07 16:09:01 UTC
By simply overriding the fontconfig shared library, the issue goes away.
The following is with fontconfig-ultimate installed, and i'm going to preload the standard arch fontconfig:

LD_PRELOAD=/tmp/usr/lib/libfontconfig.so /tmp/startuptime.sh 
/tmp/startuptime.sh: riga 3:  7602 Terminato               /tmp/mysleep 999

real    0m0.376s
user    0m0.000s
sys     0m0.003s

On a much more powerfull i5 cpu, the difference is still there; i've about 0.1seconds difference in favour of vanilla fontconfig.
Comment 5 Peter 2016-03-29 17:47:57 UTC
Same problem here. A git bisect shows this as the offending commit:

https://cgit.freedesktop.org/fontconfig/commit/?id=f44bfad235e63bb792c38e16ae1fbd281ec1453b
Comment 6 Peter 2016-03-29 18:25:55 UTC
To be more precise, the commit mentioned above adds a call to FcDirScanOnly() which causes all the stat() calls Antonio has seen. FcDirScanOnly() will *always* be called, even if the cache turns out to be perfectly valid.

To give you some more numbers, a "time fc-list" in a terminal went from ~30ms with fontconfig 2.11.1 to ~200ms with fontconfig 2.11.94. As a result, seemingly "simple" applications like dmenu show a noticeable lag on startup. I'm on an i7-3770 with 32GB RAM, so neither CPU speed nor the size of IO cache should be an issue here.

I'm not familiar with fontconfig's code, but I noticed that FcCacheDirsValid() gets called 18 times. Is that neccessary? I added some ugly static variables to make fontconfig "cache" the first return value of FcCacheDirsValid() and I'm back at my ~30ms. Thus, *one* call to FcDirScanOnly() is just fine.
Comment 7 ebiggers3 2016-03-30 02:58:54 UTC
I have been encountering this bug after upgrading from fontconfig 2.11.1-2 to fontconfig 2.11.94-1 yesterday.

I can confirm the previous post that places the blame on the following commit:

commit f44bfad235e63bb792c38e16ae1fbd281ec1453b
Author: Akira TAGOH <akira@tagoh.org>
Date:   Thu Jun 5 19:06:02 2014 +0900

    Workaround another race condition issue
    
    See https://bugzilla.redhat.com/show_bug.cgi?id=921706

Also, the main reason for the performance regression is not the stat() calls per se, but rather the inefficient "string sets" which take n^2 time to build, causing millions of string comparisons to occur when any application is started.  See FcStrSetMember(), called by _FcStrSetAppend().

Still, the entire "directory scan" seems unnecessary to me.  I don't yet fully understand what problem this change was meant to solve, but in my opinion it's not acceptable to iterate through all font files.  The purpose of the fontconfig cache is to make that unnecessary, is it not?
Comment 8 Antonio Orefice 2016-03-31 10:25:15 UTC
I don't know how much or even if it is relevant, but some further tests show that uninstalling xorg fonts makes things fast again:
https://bbs.archlinux.org/viewtopic.php?id=209687
Comment 9 Antonio Orefice 2016-03-31 19:07:26 UTC
Please ignore the previous one, it is just that there are a lot of items in the arch xorg-fonts packages; thus the slowness.
Comment 10 Mingye Wang (Arthur2e5) 2016-04-03 17:28:13 UTC
This is also encountered by @xiaqqiax (telegram-bridged) on #archlinux-cn@freenode.net. He was using 2.11.94, and got some 1-minute startup time due to his bad habit of putting fontforge SFDirs (one file per glyph!) in ~/.fonts (which didn't trigger anything that bad in 2.11.1).
Comment 11 Qi Xiao 2016-04-03 17:49:45 UTC
Confirming Arthur Wang's report here.
Comment 12 msnduy 2016-04-05 00:52:22 UTC
Noob here.

I have noticed that there is an inefficiency in the function: FcCacheDirsValid (That was newly added).
The only value that it is really using is "FcCache::dirs_count" so the whole stuff around "FcStrSet" is totally rubbish. One could simply rewrite the "FcDirScanOnly" function so that it only counts the directories (dirs_count) without all that stringset stuff.

https://gist.github.com/anonymous/5117f5ac08ae50f38e12ddebd1fb2e41

(Had a hard time writing that code, my C is a little rusty...)

Note: The patch compiles but I haven't tried it yet.
Comment 13 Akira TAGOH 2016-04-06 06:07:28 UTC
should be better in the latest git. please test.
Comment 14 Antonio Orefice 2016-04-06 15:16:16 UTC
atm it doesn't build for me:

make[1]: Entering directory '/tmp/fontconfig/doc'
make[1]: '.gitignore' is up to date.
make[1]: Leaving directory '/tmp/fontconfig/doc'
make  all-recursive
make[1]: Entering directory '/tmp/fontconfig'
Making all in fontconfig
make[2]: Entering directory '/tmp/fontconfig/fontconfig'
make[2]: Leaving directory '/tmp/fontconfig/fontconfig'
Making all in fc-blanks
make[2]: Entering directory '/tmp/fontconfig/fc-blanks'
  GEN      fcblanks.h
  File "./fc-blanks.py", line 50
    raise RuntimeError, "Unexpected escape code"
                      ^
SyntaxError: invalid syntax
Makefile:592: recipe for target 'fcblanks.h' failed
make[2]: *** [fcblanks.h] Error 1
make[2]: Leaving directory '/tmp/fontconfig/fc-blanks'
Makefile:578: recipe for target 'all-recursive' failed
make[1]: *** [all-recursive] Error 1
make[1]: Leaving directory '/tmp/fontconfig'
Makefile:462: recipe for target 'all' failed
make: *** [all] Error 2
Comment 15 Peter 2016-04-06 16:51:37 UTC
@Akira TAGOH: Yes, git is fine again. Thank you! :)
Comment 16 Akira TAGOH 2016-04-07 03:02:36 UTC
(In reply to Antonio Orefice from comment #14)
> make[2]: Entering directory '/tmp/fontconfig/fc-blanks'
>   GEN      fcblanks.h
>   File "./fc-blanks.py", line 50
>     raise RuntimeError, "Unexpected escape code"
>                       ^
> SyntaxError: invalid syntax

Fixed in git. should works now.
Comment 17 ebiggers3 2016-04-12 05:03:12 UTC
I upgraded to version 2.11.95 and the performance regression appears to be fixed.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.