staging.inyokaproject.org

Das Phänomen taucht in letzter Zeit (seit 13.12.2020) öfters auf. Es schlägt sich beim nächsten Boot in "start tree-log replay" beim Mounten wieder:

2020-12-13T15:54:16+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2020-12-14T19:23:58+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2020-12-21T16:05:14+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2020-12-22T14:35:46+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2021-02-07T14:34:33+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2021-02-26T08:46:59+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2021-02-26T08:55:57+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2021-02-27T16:41:31+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2021-03-07T17:21:18+0100 babelfish kernel: BTRFS info (device sdd3): start tree-log replay
2021-03-13T13:53:43+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2021-03-24T20:06:58+0100 babelfish kernel: BTRFS info (device sdc3): start tree-log replay
2021-04-08T16:44:10+0200 babelfish kernel: BTRFS info (device sdc3): start tree-log replay

Die letzten Paketänderungen vor dem ersten Mal:

Start-Date: 2020-12-12  17:31:30
Commandline: apt-get dist-upgrade --yes
Requested-By: robert (1000)
Install: linux-modules-5.4.0-58-generic:amd64 (5.4.0-58.64, automatic), linux-image-5.4.0-58-generic:amd64 (5.4.0-58.64, automatic), linux-headers-5.4.0-58:amd64 (5.4.0-58.64, automatic), linux-headers-5.4.0-58-generic:amd64 (5.4.0-58.64, automatic), linux-modules-extra-5.4.0-58-generic:amd64 (5.4.0-58.64, automatic)
Upgrade: linux-headers-generic:amd64 (5.4.0.56.59, 5.4.0.58.61), linux-libc-dev:amd64 (5.4.0-56.62, 5.4.0-58.64), linux-image-generic:amd64 (5.4.0.56.59, 5.4.0.58.61), python-lxml:amd64 (4.5.0-1ubuntu0.1, 4.5.0-1ubuntu0.2), python3-lxml:amd64 (4.5.0-1ubuntu0.1, 4.5.0-1ubuntu0.2), linux-generic:amd64 (5.4.0.56.59, 5.4.0.58.61)
End-Date: 2020-12-12  17:34:32

Start-Date: 2020-12-12  17:38:01
Commandline: apt install audacity
Requested-By: robert (1000)
Install: audacity:amd64 (2.3.3-1build1), libflac++6v5:amd64 (1.3.3-1build1, automatic), libsuil-0-0:amd64 (0.10.6-1, automatic), libvamp-hostsdk3v5:amd64 (2.9.0-1build1, automatic), audacity-data:amd64 (2.3.3-1build1, automatic), libportsmf0v5:amd64 (0.1~svn20101010-5ubuntu2, automatic)
End-Date: 2020-12-12  17:38:18

Ist das jemandem von Euch auch schon passiert? Könnte vielleicht an Kernel 5.4.0-58.64 liegen? Meine Suche hat leider nix ergeben. Andere Ideen?

Ich hab mich noch nicht getraut btrfs produktiv zu nutzen, weil das noch lange nicht den Reifegrad von ext4 hat und die Reparatur komplex sein kann.

Ein read-only (Re)mount passiert ja nur, wenn es nicht behebbare Fehler in Verbindung mit dem Dateisystem gibt - lässt sich da irgendetwas im Log (z.B. dmesg) dazu finden, wenn das im Betrieb passiert?

seahawk1986 schrieb:

Ich hab mich noch nicht getraut btrfs produktiv zu nutzen, weil das noch lange nicht den Reifegrad von ext4 hat und die Reparatur komplex sein kann.

Ja, ich mache recht häufig Backups. 😉 Dank borg geht das ziemlich fix. Ich finde an btrfs attraktiv, dass es Prüfsummen hat, so dass auch tatsächlich Fehler in Dateien entdeckt werden können. Und natürlich die Möglichkeit Snapshots zu erstellen. Ich glaube, die Hauptprobleme liegen bei RAID5/6.

Ein read-only (Re)mount passiert ja nur, wenn es nicht behebbare Fehler in Verbindung mit dem Dateisystem gibt - lässt sich da irgendetwas im Log (z.B. dmesg) dazu finden, wenn das im Betrieb passiert?

Ich hatte schon öfter danach geschaut, aber nix gefunden - vermutlich, weil das Journal nicht mehr geschrieben werden konnte. Vorführeffekt: beim letzten Mal findet sich tatsächlich etwas. Dies ist das Ende des Journals des vorherigen Boots:

Apr 08 16:36:43 kernel: BTRFS critical (device sdc3): corrupt leaf: root=1 block=371289161728 slot=216, bad key order, prev (18446744073709551605 0 394924130304) current (18446744073709542901 0 395997872128)
Apr 08 16:36:43 kernel: BTRFS error (device sdc3): block=371289161728 write time tree block corruption detected
Apr 08 16:36:43 kernel: BTRFS: error (device sdc3) in btrfs_commit_transaction:2279: errno=-5 IO failure (Error while writing out transaction)
Apr 08 16:36:43 kernel: BTRFS info (device sdc3): forced readonly
Apr 08 16:36:43 kernel: BTRFS warning (device sdc3): Skipping commit of aborted transaction.
Apr 08 16:36:43 kernel: BTRFS: error (device sdc3) in cleanup_transaction:1832: errno=-5 IO failure
Apr 08 16:36:43 kernel: BTRFS info (device sdc3): delayed_refs has NO entry

Fragt sich nur, was der ominöse IO-Fehler sein soll. SMART sieht unverdächtig aus (hängt an).

Ich habe mal nach "delayed_refs has NO entry" gesucht, aber das war nicht sehr erfolgreich. Auch die Suche nach "errno=-5 IO failure (Error while writing out transaction)" war bisher nicht so hilfreich.

Eine Zeitlang hatte ich mal vermutet, dass das nur nach Sleep und Wakeup passiert, aber da bin ich mir nicht so sicher. Auffällig ist, dass das seit einer Weile gehäuft vorkommt und ich könnte mir vorstellen, dass das am Kernel liegt.

Ich habe mal nach "bad key order, prev" gesucht und einen Kernel-Bug gefunden. Das ist allerdings 5.0.0, wurde aber erst Mitte Dezember gefixt. Und leider sehen die anderen Meldungen so gar nicht aus wie in meinem Fall.

Noch irgendwer irgendwelche Ideen?

rklm schrieb:

Apr 08 16:36:43 kernel: BTRFS error (device sdc3): block=371289161728 write time tree block corruption detected

https://btrfs.wiki.kernel.org/index.php/Tree-checker#For_end_users liest sich für mich so, also ob die Entwickler wissen, dass das passieren kann, aber noch nicht sicher sind, unter welchen Bedingungen das auftritt:

Please report to btrfs mail list <linux-btrfs@vger.kernel.org> first.

If it's write time corruption

Normally this means runtime memory corruption, either memory is unreliable or some other kernel memory corruption is causing the problem. Reporting to the mail list will help end user to pin down the cause by some extent. But for write time corruption, since the corruption is prevented, the fs is not further corrupted. But a btrfs check --readonly is still recommended to make sure the fs is OK.

Ich würde da auch mal den RAM überprüfen, nicht dass da unerwartet Bits flippen.

seahawk1986 schrieb:

https://btrfs.wiki.kernel.org/index.php/Tree-checker#For_end_users liest sich für mich so, also ob die Entwickler wissen, dass das passieren kann, aber noch nicht sicher sind, unter welchen Bedingungen das auftritt:

Please report to btrfs mail list <linux-btrfs@vger.kernel.org> first.

If it's write time corruption

Normally this means runtime memory corruption, either memory is unreliable or some other kernel memory corruption is causing the problem. Reporting to the mail list will help end user to pin down the cause by some extent. But for write time corruption, since the corruption is prevented, the fs is not further corrupted. But a btrfs check --readonly is still recommended to make sure the fs is OK.

Interessant. Danke für den Fund!

Ich würde da auch mal den RAM überprüfen, nicht dass da unerwartet Bits flippen.

Gute Idee! Memtest bleibt wahlweise nach relativ kurzer Zeit stecken oder bootet den Rechner neu. Das sieht nicht so gut aus. Mal sehen, ob ich identifizieren kann, welches Paar Speicherbänke problematisch ist.

rklm schrieb:

seahawk1986 schrieb:

Ich würde da auch mal den RAM überprüfen, nicht dass da unerwartet Bits flippen.

Gute Idee! Memtest bleibt wahlweise nach relativ kurzer Zeit stecken oder bootet den Rechner neu. Das sieht nicht so gut aus. Mal sehen, ob ich identifizieren kann, welches Paar Speicherbänke problematisch ist.

Also, mit den 8GB, die ich später gekauft und dazugesteckt habe, bleibt Memtest86 im zweiten Test ("Address test, own address Parallel") reproduzierbar bei 55% stecken: Bildschirm friert ein und nix geht mehr. Mit den anderen beiden Riegeln läuft der gesamte Test ohne Fehler durch. Da haben wir wohl den Schuldigen.

Ich habe auch festgestellt, dass die Timings der beiden Riegelpaare sich etwas unterscheiden: die originalen 4GB haben CAS 5-5-5-18, während die neueren 8GB CAS 5-5-5-15 haben. Entweder habe ich da beim Kauf nicht aufgepasst oder es gab keine mit dem selben Timing. Kann das die neueren Riegel beschädigt haben?

Bei CAS 5-5-5-15 ist die t_RAS kleiner als bei CAS 5-5-5-18, d.h. der neue Speicher sollte da drei ns weniger zwingend nötige Wartezeit haben als der alte. Bei so einem kleinen Sprung dürfte IMHO auch nicht viel thermisch passieren , das dem RAM schaden könnte (aber wenn man ein Modul zu Latenzen zwingt, die kürzer als der angegebene Wert sind, kann der RAM fehlerhaft arbeiten) und generell würde ich erwarten, dass das System immer die Timings des langsamsten Moduls als Voreinstellung nimmt, so dass der neue RAM-Riegel es wegen dem schon vorhandenen etwas gemütlicher angehen lassen kann.

Falls da niemand an den Timings des RAM gedreht hat (es gibt auch Mainboards (z.B. bestimmte Gaming-Modelle von ASUS), die standardmäßig den RAM leicht übertakten - falls das bei deinem Modell der Fall ist, würde ich mal schauen, was passiert, wenn man das auf Normalwerte zurückschraubt), würde ich eher an eine andere Ursache für den Defekt denken - z.B. bei einer elektrostatische Entladung bei ungenügender Erdung beim Einbau oder eine sonstige Überspannung - korreliert das Auftreten des Problems zeitlich mit dem Einbau des Speichers oder ist das unabhängig davon aufgetreten?

seahawk1986 schrieb:

Bei CAS 5-5-5-15 ist die t_RAS kleiner als bei CAS 5-5-5-18, d.h. der neue Speicher sollte da drei ns weniger zwingend nötige Wartezeit haben als der alte. Bei so einem kleinen Sprung dürfte IMHO auch nicht viel thermisch passieren , das dem RAM schaden könnte (aber wenn man ein Modul zu Latenzen zwingt, die kürzer als der angegebene Wert sind, kann der RAM fehlerhaft arbeiten) und generell würde ich erwarten, dass das System immer die Timings des langsamsten Moduls als Voreinstellung nimmt, so dass der neue RAM-Riegel es wegen dem schon vorhandenen etwas gemütlicher angehen lassen kann.

So ungefähr hatte ich mir das auch zusammengereimt. Danke für die Erläuterung!

Falls da niemand an den Timings des RAM gedreht hat (es gibt auch Mainboards (z.B. bestimmte Gaming-Modelle von ASUS), die standardmäßig den RAM leicht übertakten - falls das bei deinem Modell der Fall ist, würde ich mal schauen, was passiert, wenn man das auf Normalwerte zurückschraubt),

Das Board hat zwar im BIOS jede Menge Möglichkeiten an den Timings im Detail zu drehen und zu übertakten, aber diese Einstellungen waren immer auf "Standard" oder "auto", soweit ich das erinnere. Jedenfalls habe ich da auf keinen Fall etwas geändert. Ich kann es jetzt aber nicht mehr nachvollziehen, da jeder Speicherwechsel das BIOS auf die Voreinstellungen zurücksetzt - was ja auch sinnvoll ist.

würde ich eher an eine andere Ursache für den Defekt denken - z.B. bei einer elektrostatische Entladung bei ungenügender Erdung beim Einbau oder eine sonstige Überspannung - korreliert das Auftreten des Problems zeitlich mit dem Einbau des Speichers oder ist das unabhängig davon aufgetreten?

Völlig unabhängig. Der Speicher ist seit Oktober 2015 verbaut, das Phänomen tritt erst seit letzten Dezember auf. Und ich habe in der Zeit auch nicht am System geschraubt. Meine aktuelle Arbeitshypothese ist, dass der Speicher vielleicht vorher schon einen Schlag hatte und das Problem sich erst mit einem Kernel-Update bemerkbar machte, weil vielleicht die Speicherzugriffsmuster anders sind oder Dinge woanders im RAM landen.

Ich bin mir jedenfalls mittelmäßig sicher, dass ich damals nach dem Einbau Memtest habe durchlaufen lassen um sicher zu gehen, dass der neue Speicher funktioniert. Allein schon, weil man ja die sporadische Natur von solchen Fehlern kennt, habe ich das bestimmt auch über Nacht ein paar Runden laufen lassen, so, wie ich mich kenne. 😉