Seit einigen Tagen beobachte ich in den Log-Dateien wiederholt Einträge der folgenden Art:
Aug 4 17:19:40 desktop-ubuntu kernel: [22801.032322] INFO: task updatedb.mlocat:7661 blocked for more than 120 seconds. Aug 4 17:19:40 desktop-ubuntu kernel: [22801.034164] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Die Fehlermeldung tritt zu einer Uhrzeit auf, zu der normalerweise das Backup unbeaufsichtigt läuft. Die erste Vermutung ist deshalb, daß der Fehler sich bei intensiver Festplatten-Nutzung einstellt. Als Ursache befürchte ich zunächst einen Hardware-Defekt oder einen Fehler in der VirtualBox-Virtualisierungsschicht für den Raw-Device-Zugriff (ich verwende keine Container-Dateien, sondern direkten Zugriff auf die Platte). Allerdings läßt sich die Meldung mit einem Streßtest mittels iozone, bonnie++ oder fio in der virtuellen Maschine nicht provozieren; auch dann nicht, wenn mehrer Prozesse davon parallel laufen. Ebenso schweigt sich das Windows-Ereignisprotokoll über den Zeitraum aus, auch ein dazugezogenes CrystalDisk zeigt keine SMART-Fehler. Nachdem die Performance-Messungen eine anständige Leistung zeigen, bin ich zunächst wieder etwas beruhigt.
Eine Google-Recherche liefert schnell einen Link auf Ronny Egners Blog. Der dort angesprochene Workaround (vm.dirty_ratio von 40 auf 10 zu setzen) greift bei mir aber nicht, da dieser Wert bereits eingetragen ist. Den an anderer Stelle erwähnten Effekt, daß beinahe das gesamte RAM für Caches gebraucht wird, kann ich mit vmstat dagegen nachvollziehen.
Um der Sache auf den Grund zu gehen, starte ich manuell /etc/cron.daily/mlocate und rsnapshot. Nach nur wenigen Sekunden Laufzeit erscheinen die bekannten Kernel-Meldungen wieder. Es muß also etwas mit dem besonderen Zugriffsmustern dieser beiden Programme zu tun haben. Unglücklicherweise starten die beiden Programme auch parallel, weil morgens nach dem Wake-On-LAN-Event sofort das Backup startet und dank anacron auch der tägliche locate-Lauf.
Ein Blick in /etc/cron.daily/mlocate offenbart, daß updatedb.mlocate mit ionice -c3 gestartet wird. Das erklärt zumindest, wie es zu der Meldung kommt: Bei -c3 priorisiert mlocate so, daß es nur im IO-IDLE-Zustand läuft (um das System bei interaktiver Benutzung durch den User nicht zu verlangsamen). Offenbar lastet rsync das System aber so gut aus, daß mlocate für mehr als 2 Minuten gar nicht mehr zum Zuge kommt.
Offenbar ist es auch so, daß mlocate genau in den Pfad hinabsteigt, den rsnapshot als Ziel für seine Backups eingestellt hat und das zu einem Zeitpunkt an dem dort kräftig geschrieben wird. Dies ist natürlich besonders unpassend, da bei rsync-basierten Backup ein Vielfaches an Dateien erzeugt wird (Hardlinks). In der ersten Phase eines rsnapshot-Laufes wird auch das ältestes Backup gelöscht. Eventuell ist genau das kritische Zugriffsmuster. Oder es liegt daran, daß BTRFS noch Probleme mit konkurrierendem Zugriffen hat.
Um die Fehlermeldung loszuwerden und die ohnehin unnötige Indizierung des Backups zu verhindern reicht es jedenfalls das Backup-Ziel-Verzeichnis als Ausnahme zu PRUNEPATHS in /etc/updatedb.conf dazuzufügen. Anschließend muß allerdings noch die Datenbank-Datei /var/lib/mlocate/mlocate.db gelöscht werden, da mlocate wohl trotz PRUNEPATH in den Pfad hinabsteigt, wenn dazu schon ein Eintrag existiert.