Booting a live session is slow - fontconfig regenerates its font cache

Bug #1749546 reported by Jean-Baptiste Lallement on 2018-02-14
52
This bug affects 8 people
Affects Status Importance Assigned to Milestone
Fontconfig
Unknown
Medium
fontconfig (Ubuntu)
High
Iain Lane
Bionic
High
Iain Lane

Bug Description

On Bionic Ubuntu Desktop booting to a live session is slow. It takes roughly 2 min on my test machine to boot from the "Try or Install Ubuntu" boot menu to a usable session.

It also takes 1 minute to logout and 17s to log in again.

ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: casper 1.388
ProcVersionSignature: Ubuntu 4.13.0-32.35-generic 4.13.13
Uname: Linux 4.13.0-32-generic x86_64
ApportVersion: 2.20.8-0ubuntu10
Architecture: amd64
CasperVersion: 1.388
CurrentDesktop: ubuntu:GNOME
Date: Wed Feb 14 16:43:19 2018
LiveMediaBuild: Ubuntu 18.04 LTS "Bionic Beaver" - Alpha amd64 (20180214)
ProcEnviron:
 TERM=xterm-256color
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=C.UTF-8
 SHELL=/bin/bash
SourcePackage: casper
UpgradeStatus: No upgrade log present (probably fresh install)

Hi,

The following bug has been reported in debian:

===

Dear Maintainer,
fontconfig now requires nano second mtime precision on files in order to
validate their freshness. squashfs does not seem to support nano second
mtime precision causing any Desktop ISO's made with live-build to regenrate
the font cache at the desktop startup leading to a very slow time to desktop.

===

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=880574

Hmm, what does "not seem to support" really mean here? are you generating a cache on non-squashfs and using it on squashfs then?

I believe that what bug reporter means is that the cache is added to the squashfs during the build of the livecd and at boot when FC tries to check the freshness of the cache it decides that it needs to be updated and then write a fresh one to the unionfs (I suppose)

Can you give me a log of FC_DEBUG=16 fc-cache prior to boot the desktop?

Jean-Baptiste Lallement (jibel) wrote :
Jean-Baptiste Lallement (jibel) wrote :

journal with systemd log level set to debug.

tags: added: rls-bb-incoming
description: updated
Steve Langasek (vorlon) wrote :

This is probably not a bug in casper itself, as that code hasn't changed recently, but may be a change in the desktop live session. Assigning to the Desktop Team for further investigation.

Changed in casper (Ubuntu):
assignee: nobody → Canonical Desktop Team (canonical-desktop-team)
Jean-Baptiste Lallement (jibel) wrote :

this is definitely not a bug in casper but a mix of different issues. It is currently under investigation and this bug is used as a placeholder to track the problem. Specific bugs will be filed as causes are identified.

Created attachment 138574
output of FC_DEBUG=16 fc-cache

I attached the output of FC_DEBUG=16 fc-cache before booting to an Ubuntu Desktop Live Session. This is a follow-up of the issue reported in LP (https://bugs.launchpad.net/ubuntu/+source/bluez/+bug/1754836) where, according to latest comments), the font cache is regenerated when the user session starts.
Let me know if you need more information.

Will Cooke (willcooke) wrote :

Thanks to ali1234 this was tracked down to font-config rebuilding the cache at the start of the live session. Something changed in the way fontconfig validates the caches and so they are being rebuilt at the start of the live session.

This bug is likely related: https://bugs.freedesktop.org/show_bug.cgi?id=103652

no longer affects: casper (Ubuntu)
no longer affects: casper (Ubuntu Bionic)
Changed in fontconfig (Ubuntu Bionic):
assignee: nobody → Canonical Desktop Team (canonical-desktop-team)
Will Cooke (willcooke) on 2018-04-04
Changed in fontconfig (Ubuntu Bionic):
assignee: Canonical Desktop Team (canonical-desktop-team) → Iain Lane (laney)
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in fontconfig (Ubuntu):
status: New → Confirmed
Iain Lane (laney) on 2018-04-04
Changed in fontconfig (Ubuntu Bionic):
status: Confirmed → In Progress
importance: Undecided → High
summary: - Booting a live session is slow
+ Booting a live session is slow - fontconfig regenerates its font cache
Will Cooke (willcooke) on 2018-04-04
tags: removed: rls-bb-incoming
Changed in fontconfig:
importance: Unknown → Medium
status: Unknown → Confirmed
Ubuntu QA Website (ubuntuqa) wrote :

This bug has been reported on the Ubuntu ISO testing tracker.

A list of all reports related to this bug can be found here:
http://iso.qa.ubuntu.com/qatracker/reports/bugs/1749546

tags: added: iso-testing

Created attachment 138578
cache: If nsec is zero, don't use it for comparisons

I made a (stupid?) patch. Is this a reliable way to go about falling back from nsec to non-nsec? I couldn't find a way to actually ask the question of the system directly.

We're particularly interested because this is a big cause of live image boot slowness on Ubuntu. This patch works as intended; the cache isn't regenerated on live system boot any more.

Iain Lane (laney) wrote :

I've submitted a patch on the upstream bug - hopefully will get some feedback quickly. I'm not super sure if it's a sensible approach.

The problem as I understand it:

1. You have /usr/share/fonts/* on ext4 or similar FS with nanos.
2. /usr/share/fonts has a timestamp like 1522818676.601423551.
3. You run fontconfig and it stores the timestamp in the cache file.
4. You build a squashfs from the FS. Squashfs does not support nanos.
5. The timestamp of /usr/share/fonts inside the squashfs becomes 1522818676.0.
6. Installer boots and fontconfig sees the mismatched time stamps so rebuilds the cache in the live user's home directory - which is wiped at reboot.
7. During install the squashfs is copied back to an ext4 FS.
8. User reboots and logs in.
9. /usr/share/fonts is now on a filesystem which supports nanos, but the original time stamp nanos has been lost.
10. Fontconfig decides the cache is out of date and rebuilds it again, in the new user's home directory. This happens each time a newly created user logs in, until such time as a postinst script rebuilds the system font cache.

Note steps 9 and 10 only happen on Xubuntu and maybe some other flavours, but not Ubuntu.

This means that even if you could ask the system whether the filesystem supports nanos, that wouldn't be enough. It is possible for the timestamp information to be lost/mutated through squashfs, and then copied back to a filesystem with nanos, and then there is no way to determine whether that has happened or not.

Your analysis is correct.

point 9 doesn't happen on Ubuntu (and maybe other flavours) because at the end of te installation process, some packages are removed from the target filesystem that triggers the fontconfig trigger (which runs the postinst script that regenerate the cache) So on next boot the timestamps won't have nanoseconfs but will match.

Aren't this:

(In reply to Alistair Buxton from comment #6)
> 5. The timestamp of /usr/share/fonts inside the squashfs becomes
> 1522818676.0.
> 6. Installer boots and fontconfig sees the mismatched time stamps so
> rebuilds the cache in the live user's home directory - which is wiped at
> reboot.
> 7. During install the squashfs is copied back to an ext4 FS.

and this:

> 8. User reboots and logs in.
> 9. /usr/share/fonts is now on a filesystem which supports nanos, but the
> original time stamp nanos has been lost.
> 10. Fontconfig decides the cache is out of date and rebuilds it again, in
> the new user's home directory. This happens each time a newly created user
> logs in, until such time as a postinst script rebuilds the system font cache.

actually the same thing happening twice? The nanosecond portion of the timestamp is lost when the squashfs is built, and it's still not there when it's copied to the target system, but the fontconfig cache has nanos in it.

In that case, my proposed fix fixes this. I tried with a modified Xubuntu ISO, and after installation:

laney@bionic:~$ ls -l .cache
total 24
-rw-rw-r-- 1 laney laney 5 Apr 5 12:52 blueman-applet-1000
drwxr-xr-x 2 laney laney 4096 Apr 5 12:52 gstreamer-1.0
-rw-r--r-- 1 laney laney 0 Apr 5 13:05 motd.legal-displayed
drwx------ 2 laney laney 4096 Apr 5 12:53 obexd
drwx------ 2 laney laney 4096 Apr 5 12:52 sessions
drwxrwxr-x 2 laney laney 4096 Apr 5 13:01 update-manager-core
-rw-rw-r-- 1 laney laney 381 Apr 5 12:52 xfce4-indicator-plugin.log

(laney@bionic:~$ stat /usr/share/fonts
...
Modify: 2018-04-04 06:44:44.000000000 +0100
laney@bionic:~$ FC_DEBUG=16 fc-cache
FC_DEBUG=16
FcCacheTimeValid dir "/usr/share/fonts" cache checksum 1522820684.549609025 dir checksum 1522820684.0
tv_nsec == 0, ignoring nanoseconds)

Yes, your current patch handles both cases.

My point was that if you "improve" the patch to check whether the filesystem supports nanos it would no longer handle the second case.

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package fontconfig - 2.12.6-0ubuntu2

---------------
fontconfig (2.12.6-0ubuntu2) bionic; urgency=medium

  * Upload proposed patch from upstream bug #103652. If the fontconfig cache
    was built on a system that has nanosecond timestamps and then later
    transplanted to one that doesn't - for example by mksquashfs as part of a
    live CD build - we consider the cache invalid and rebuild it during the
    boot process. Depending on the fonts involved, this can take a significant
    amount of time and potentially cause knock-on timeouts. The approach in
    this patch is to ignore the nanosecond portion of the cache's value if we
    get 0 when stat()ing the referenced directory, meaning it is considered
    fresh if the rest of the timestamp matches. (LP: #1749546)

 -- Iain Lane <email address hidden> Thu, 05 Apr 2018 17:13:52 +0100

Changed in fontconfig (Ubuntu Bionic):
status: In Progress → Fix Released
PeppeKorg (peppekorg) wrote :

Tested with xubuntu 20180408 live - boot process faster than before. Is there anything else we should check specifically?

Jeremy Soller (jackpot51) wrote :

I can also confirm that this fixed the issue in Pop!_OS and elementary OS.

-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/fontconfig/fontconfig/issues/44.

Changed in fontconfig:
status: Confirmed → Unknown
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.