blog · git · desktop · images · contact

fontconfig-Caches vs. /tmp

2018-06-02

Mein Setup ist eigentlich nicht so komplex. Das System bootet in eine Text-Konsole, damit ich mich auf tty1 einloggen kann. Mache ich das, so entscheidet meine ~/.bashrc, automatisch startx zu starten. Es gibt keinen Display-Manager. Meine ~/.xinitrc enthält dann ein paar Programme, die automatisch gestartet werden sollen, das sind hauptsächlich ein paar Terminals, die Leisten am Bildschirmrand und schlussendlich der Window-Manager. Und es wird ein Wallpaper gesetzt. Das war’s dann aber auch.

Obwohl also kaum welche dieser „modernen“ „fetten“ „bloated“ Software involviert ist, hatte ich da immer einen kurzen Freeze nach dem Start von X und vor dem Start des Window-Managers. Das war bisher so kurz, dass es mich nicht weiter gestört hat, gestern wurde es aber deutlich schlimmer.

Debugging des Problems

Mir war nicht auf Anhieb eine Ursache ersichtlich. Ich habe dann meine ~/.xinitrc zusammengestaucht, sodass sie nur noch

openbox

enthielt und sonst nichts mehr. Openbox habe ich gewählt, weil das ein ausgereiftes Programm ist, was ja wohl keinen Quatsch machen wird, oder? Es könnte sich ja schließlich um einen Bug in meinem eigenen Window-Manager handeln. Hat aber nicht geholfen. Ein Rechtsklick, um das Openbox-Menü zu öffnen, hat immer noch für einen 3-4 sekündigen Hänger gesorgt.

Aber nur beim ersten Mal. Das zweite Öffnen des Menüs war schnell. Auch fiel auf, dass all das nur beim ersten Mal nach dem Booten passierte.

So, und jetzt? In eine zweite Konsole auf tty2 eingeloggt und gestartet, danach sofort X auf der anderen Konsole:

while true; do ps aux >"$(date +%T.%N)"; done

Das förderte zu Tage, dass openbox so zwischen 50 und 80% der CPU-Zeit gefressen hat und auch für einige Sekunden am Stück. Was tut das Ding?

Aus Neugier bin ich dann mal zu meiner originalen ~/.xinitrc zurück und habe mir die Prozessliste hier angeschaut. Es zeigte sich dann, dass so ziemlich jeder X-Client große Mengen an CPU-Zeit haben wollte. Jedes Terminal, jede Bar, der Window-Manager – aber Tools wie sxhkd nicht.

Es schien also nicht am Window-Manager zu liegen und auch kein generelles X-Problem zu sein. Aber was machen diese Programme denn da alle? Zeit für strace.

In der ~/.xinitrc einen der Aufrufe von

terminal -e foo

in

strace -tt -ff -o /tmp/term.log terminal -e foo

geändert.

Und dann sah man’s:

...
06:48:17.516879 stat("/usr/share/fonts/100dpi/UTI___10-ISO8859-1.pcf.gz", {st_mode=S_IFREG|0644, st_size=5080, ...}) = 0
06:48:17.516914 openat(AT_FDCWD, "/usr/share/fonts/100dpi/UTI___10-ISO8859-1.pcf.gz", O_RDONLY) = 5
06:48:17.516939 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
06:48:17.516959 fstat(5, {st_mode=S_IFREG|0644, st_size=5080, ...}) = 0
06:48:17.516981 mmap(NULL, 5080, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7efcdda1b000
06:48:17.517006 close(5)                = 0
06:48:17.517211 munmap(0x7efcdda1b000, 5080) = 0
06:48:17.517235 openat(AT_FDCWD, "/usr/share/fonts/100dpi/UTI___10-ISO8859-1.pcf.gz", O_RDONLY) = 5
06:48:17.517260 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
06:48:17.517280 fstat(5, {st_mode=S_IFREG|0644, st_size=5080, ...}) = 0
06:48:17.517302 mmap(NULL, 5080, PROT_READ, MAP_PRIVATE, 5, 0) = 0x7efcdda1b000
06:48:17.517324 close(5)                = 0
06:48:17.517457 munmap(0x7efcdda1b000, 5080) = 0
...

Das wurde für jede Font-Datei in meinem System gemacht. Und jedes Programm, das irgendwas mit Fonts zu tun hat, tat das. sxhkd ist nur ein Hotkey-Daemon, der hat nichts mit Text zu tun, war also schnell fertig und tauchte nicht in der Liste auf. Aber die Bars, Terminals und der WM, die zeigen alle Text an und grasten dann wie treudoofe Schafe alle Fonts ab.

Wie viele Fonts gibt’s denn da? Die Calls da oben sind ja in unter einer Millisekunde fertig, also wieso dauert das insgesamt so lang? Tja, hier sind ein paar Zahlen von ncdu:

--- /usr/share/fonts ---------------------
   24.3 MiB [##########]     39 /TTF
   17.0 MiB [######    ]  1,897 /100dpi
   15.7 MiB [######    ]  1,897 /75dpi
   10.8 MiB [####      ]    584 /misc
    7.0 MiB [##        ]      2 /noto
    5.9 MiB [##        ]     26 /OTF
    3.2 MiB [#         ]     38 /gsfonts
    2.8 MiB [#         ]     60 /Type1
  776.0 KiB [          ]     54 /encodings
  704.0 KiB [          ]     13 /local
  600.0 KiB [          ]      8 /cantarell
  208.0 KiB [          ]     18 /util
   16.0 KiB [          ]      3 /cde
   12.0 KiB [          ]      2 /cyrillic
    4.0 KiB [          ]         .uuid

Die Größenangaben in Megabyte sind nicht so wichtig, es gibt aber knapp 2000 Dateien in /usr/share/fonts/100dpi und …/75dpi.

Aber was genau ist denn jetzt los? Warum werden diese Fonts verarbeitet? Warum immer nur beim ersten Start? Am Ende der strace-Log sieht man dann das hier:

06:54:55.253048 access("/var/cache/fontconfig", W_OK) = -1 EACCES (Permission denied)
06:54:55.253078 access("/tmp/cache-void/fontconfig", W_OK) = 0

A-ha.

$XDG_CACHE_HOME liegt in /tmp

Meine ~/.bashrc tut das:

export XDG_CACHE_HOME=/tmp/cache-$USER
install -dm0700 "$XDG_CACHE_HOME"

Viele Programme halten sich heute an Vorschläge von freedesktop.org, werten also Variablen wie $XDG_CACHE_HOME aus. Da landet ein Haufen Müll:

So Zeugs will ich regelmäßig löschen. Zu oft war irgendein gut gemeinter Cache die Ursache eines Problems. Irgendein Programm entscheidet etwas, steckt das in seinen Cache und dann klebt das da für viel zu lange Zeit drin fest. Das kann wirklich lästig sein, Fehlersuche erschweren und für Fehlverhalten sorgen.

Manche Leute gehen sogar so weit und packen ihr ganzes $HOME in den RAM. Ich halte das auch für eine gute Idee, bin bloß bisher viel zu faul gewesen, das bei mir auch umzusetzen. Die Sache ist einfach die: Wenn ich den Rechner starte, dann will ich einen sauberen, wohldefinierten Stand haben. Überreste von vorherigen Sessions können zwar manchmal nützlich sein, meistens fühlen die sich aber wie Müll von der letzten Party an.

Der fontconfig-Cache

Nungut, bloß legt fontconfig seinen Cache eben auch unterhalb von $XDG_CACHE_HOME ab. Und wie man oben ja sah, dauert das Erstellen des Caches sehr lange. Was macht man da?

Was zunächst einmal auffällt: Die strace-Logs zeigen, dass die Programme Dateien unterhalb von /usr/share/fonts verarbeiten und dann nach /var/cache/fontconfig zu schreiben versuchen. Das heißt, dass es

  1. einen systemweiten Cache von fontconfig gibt und
  2. dieser veraltet ist.

Dass ich $XDG_CACHE_HOME nach /tmp zeigen lasse, hat das Problem nur sichtbar gemacht, war aber nicht die Ursache davon. Eigentlich geht es hier gar nicht um den Cache meines Users.

In Arch Linux gibt es eigentlich einen pacman hook, der automatisch den Systemcache von fontconfig aktualisiert:

$ cat /usr/share/libalpm/hooks/fontconfig.hook
[Trigger]
Type = File
Operation = Install
Operation = Upgrade
Operation = Remove
Target = usr/share/fonts/*

[Action]
Description = Updating fontconfig cache...
When = PostTransaction
Exec = /usr/bin/fc-cache -s

Leider bin ich nicht tief genug vorgedrungen, um herauszufinden, warum der Cache denn nicht mehr aktuell war. Ich hatte es eilig und habe einfach fc-cache -s als root gestartet.

Was ist überhaupt in dem Cache drin? Braucht man den wirklich? Ja, naja, den braucht man durchaus – alleine, dass das Erstellen so lange dauert, ist ein guter Indikator dafür. Nach meinem jetzigen Kenntnisstand öffnet fontconfig jede Fontdatei, dekomprimiert sie dabei vielleicht auch noch und liest Attribute wie die folgenden aus:

Ein Eindruck kann man gewinnen, indem man den Cache mal löscht und direkt danach FC_DEBUG=32 fc-list aufruft.

Ein Workaround für die Zukunft

Ich will auch weiterhin solche Caches in /tmp liegen haben. Außerdem war das ja überhaupt nicht die Ursache des Problems: Ein persistenter fontconfig-Cache im Homeverzeichnis des Users hätte nur versteckt, dass der systemweite Cache kaputt ist, und genau solche Probleme würde ich gerne vermeiden. Stattdessen enthält meine ~/.xinitrc nun das hier, bevor andere Programme gestartet werden:

echo 'Running fc-list to make sure fontconfig cache is up to date ...'
fc-list >/dev/null 2>&1
echo 'fc-list done.'

Das stößt dann ein Update meines User-Caches an, welcher in /tmp liegen wird. Dieser Cache ist nur für die paar wenigen Fonts relevant, die ich manuell in ~/.fonts werfe – der Kram aus /usr/share/fonts landet da gar nicht. Wenn ich das am Anfang der Datei so ausführe, heißt das implizit auch, dass alle folgenden Programme immer mit einem frischen Cache arbeiten, anstatt ihn nochmal selbst neu zu bauen – genau das ist vorher passiert, weil die alle gleichzeitig gestartet sind und einen veralteten Cache vorgefunden haben.

Das echo ist auch wichtig. Am Anfang meiner ~/.xinitrc habe ich das hier:

#!/bin/bash

[[ "$1" != logging ]] && exec systemd-cat "$0" logging

Das sammelt jegliche Ausgaben der gestarteten Programme in meinem journal auf. (Da Dateideskriptoren vererbt werden, gilt das auch für Programme, die später über sxhkd und damit auch über dmenu gestartet werden.) Das journal von systemd ist immer noch recht kontrovers, macht aber zwei praktische Dinge:

  1. Es „rotiert“ automatisch die Logs, also muss ich das nicht mehr selbst bauen.
  2. Es fügt automatisch Timestamps hinzu.

(Ja, das sind keine Alleinstellungsmerkmale. Wie gesagt, es ist kontrovers.)

Wenn ich das nächste Mal also wieder solche Freezes beim Start habe, kann ich in journalctl -ra schauen. Die Timestamps werden dann schnell zeigen, ob es wieder an fontconfig lag.

Comments?