[erledigt] Probleme mit Kernel Treiber TT6400 für linux 5.16

    Hallo S:oren ,


    ich habe vor einiger Zeit mein Fedora auf Kernel 5.16 upgedated. Für die TT6400 habe ich dazu aus Deinem git den neuen Treiber für 5.16 geholt.

    Bei dem hast Du ja gegenüber dem vorhergehenden Stand einiges geändert.


    Seit dem bekomme ich, meistens bei Tuner 2, Tuner 1 hat es aber auch schon getroffen, unregelmäßig, aber immer wieder "I2C transfer error" Fehler im Log:

    Das betrifft sowohl verschlüsselte, als auch öffentliche Sender.

    Der Tuner ist ab dem Moment nicht mehr benutzbar.

    Ein VDR-Neustart hilft dann nicht, erst ein Neuladen des Treibers belebt den Tuner dann wieder.

    Um andere Probleme auszuschließen, habe ich vor kurzem mal den alten Treiber von 5.15 für Kernel 5.16 installiert und nutze den seit dem. Damit treten diese Probleme nicht auf.


    Ich nutze hier die TT6400 (frontend 0 und 1) und die DVBSky S952 V3 (frontend 2 und 3). Beide Karten nutzen jeweils 1 Kabel (devicebonding).

    Beide Tuner der TT6400 nutze ich im Transfer-Mode.


    Viele Grüße

    kamel5

    VDR 2.6.6: ASUS Prime X470-PRO, Ryzen 7 5700X, 64GB, 6TB HD, GT1030, Fedora 39 Kernel 6.8 X86_64, Devicebonding 2 x 1 auf 2, TT6400, DVBSky S952 V3

    Git-Repo: gitlab.com/kamel5

    Ja, es hat sich Einiges geaendert. I2C-NAKs gehen jetzt (z.B. fuer i2c-detect), die Umschaltzeiten sind bei mir besser, die I2C-Fehlermeldungen sind ausfuehrlicher und nuetzlicher, Reads bleiben bei mir nicht mehr haengen (war ein ewiges Problem bei mir Ende letzten Jahres).


    Leider habe ich auch 2x haengende I2C-Writes in den letzten beiden Monaten beobachtet. Noch keine Zeit gehabt, da etwas zu fixen.


    Neuladen des Treibers hilft immer, weil dann die Demods unabhaengig von I2C resettet werden. Die hohe Kunst waere nun, die Bus-Recovery ausschließlich ueber I2C hinzubekommen. Der eingebaute "Standard-Workaround" scheint bei dem Tuner oder Demod (evt. in Verbindung mit dem vorhandenen I2C-Gate) nicht perfekt zu funktionieren. Read-Recovery klappt bei mir, fuer Writes war offenbar der alte Workaround besser (der bei Reads aber nicht geholfen hat). Hier muss also offenbar etwas Besseres her, z.B. in Anhaengigkeit des letzten Zugriffs (R/W) oder des Line-States (ist Clock-Streching durch den Slave das Problem, oder unpassende ACKs des Slaves, oder etwas Anderes?).

    Noch besser, wenn man eine Idee haette, warum ueberhaupt mal ein I2C-Zugriff haengen bleibt. Theoretisch sollte das ja nur passieren koennen, wenn der I2C-Master mitten im Zugriff resettet wird (z.B. Neuladen des Moduls mitten im I2C-Zugriff). Aber das passiert ja im Normalbetrieb nicht. Oder habe ich etwas uebersehen?


    Gruss,

    S:oren

    Einen kurzen Blick habe ich jetzt nochmal auf die Logs geworfen. Bei mir gab es in den letzten Wochen keine einzige Meldung ueber I2C transfer errors mehr. Somit ist es fuer mich mangels Fehler extrem schwierig, hier etwas zu debuggen.


    Die gute Nachricht scheint zu sein, dass die I2C-Bus-Recovery gut funktioniert. Bevor ich Ende letzten Jahres den Code geaendert habe, gab es nach einem Fehler unendlich Fehler, bis zum Neuladen des Treibers. Jetzt failed ein einzelner Transfer, das faengt sich aber wieder. Ohne Debug-Logs sieht man leider nicht, ob zwischendurch auch Transfers fehlerfrei durchgehen. Klar ist natuerlich, dass eine fehlgeschlagene Initialisierung des Demods dann auch bis zum Neuladen des Treibers keinen sinnvollen Betrieb mehr ermoeglicht, auch wenn der I2C-Bus an sich wieder funktioniert.


    Die I2C-Taktfrequenz ist etwas "optimistisch" eingestellt, das sollte ich nochmal fixen. Nur laeuft die S2-6400 auch mit 400kHz I2C-Takt, die leichte Uebertaktung bei den standardmaeßigen 100kHz kann also eigentlich kein Problem sein.


    kamel5 , kannst Du den aktuellen Treiber nochmal mit den pci_dbg-Meldungen laufen lassen? Vielleicht ergibt sich da ein Anhaltspunkt, wo das eigentliche Problem liegt, ansonsten habe ich Moment keine Idee.


    Gruss,

    S:oren

    Zitat von S:oren

    kamel5 , kannst Du den aktuellen Treiber nochmal mit den pci_dbg-Meldungen laufen lassen? Vielleicht ergibt sich da ein Anhaltspunkt, wo das eigentliche Problem liegt, ansonsten habe ich Moment keine Idee.

    Hallo S:oren ,

    mache ich gern. Kannst Du mir noch sagen, bevor ich jetzt lange suche, wie man die pci_dbg-Meldungen aktviert.


    Grüße

    kamel5

    VDR 2.6.6: ASUS Prime X470-PRO, Ryzen 7 5700X, 64GB, 6TB HD, GT1030, Fedora 39 Kernel 6.8 X86_64, Devicebonding 2 x 1 auf 2, TT6400, DVBSky S952 V3

    Git-Repo: gitlab.com/kamel5

    Ist bei mir auch laenger her, muesste ich auch nachschauen. Der Kernel muss mit aktiviertem Debug uebersetzt werden, soweit ich mich erinnere, ansonsten kommen die ganzen Debug-Strings gar nicht in das Kernel-Image/Modul hinein. Dann gibt es auch eine Moeglichkeit, nur bestimmte Debug-Meldungen zur Laufzeit zu aktivieren.

    Als Hack hier waere es vielleicht einfacher, in der Datei saa716x_i2c.c alle pci_dbg durch pci_info zu ersetzen. Aber Du kannst es gerne auch richtig machen ;)


    Gruss,

    S:oren

    Ich habe nochmal ein Update zum 5.16er Treiber eingecheckt. Das wird nicht die Ursache des Problems beheben, dass manchmal ein Timeout auftritt. Aber vielleicht ein sinnvolleres Fehlerlog liefern, ohne weitere Kollisionen zu verursachen. Auch ist das I2C-Timing gefixt.


    Gruss,

    S:oren

    Hallo S:oren ,


    sorry, ich habe das mit dem aktualisierten Treiber jetzt erst gesehen, ich lasse das gerade neu übersetzen...


    Mit dem alten 5.16 Treiber (pci_dbg durch pci_info zu ersetzt) hatte ich gestern den Fehler wieder mal, diesmal hat sich Tuner 2 totgestellt.


    Anbei gibt es 2 Logs:

    journal-vdr-1.txt.gz enthält alle vdr Logmeldungen ab Start (um einige unwichtigen Sachen bereinigt)

    journal-SAA716x-1.txt.bz2 enthällt die pci Meldungen (sehr umfangreich, deshalb in der Mitte und am Ende gekürzt)


    Ab dieser Log-Meldung:

    Mär 12 18:30:01 vdr[3672]: [4526] frontend 1/0 timed out while tuning to channel 6 (ZDFinfo HD), tp 211347

    ist Tuner 2 "tot".


    frontend 0/0 und frontend 1/0 sind die TT6400, beide Tuner im Transfermode und gebondet, Tuner 1 liefert das Live-TV.

    frontend 2/0 und frontend 3/0 sind von der DVBSky S952 V3 (kannst Du ignorieren).


    Soweit ich das bisher mitbekommen habe, ist dieses Problem bei mir noch nicht während des normalen Live -TV aufgetreten, sondern immer während oder "kurz" nach dem Abspielen einer Aufzeichnung, wie auch in diesem Fall.

    Mär 12 18:22:57 vdr[3672]: [372041] dvbplayer thread ended (pid=3672, tid=372041)


    Folgende Fälle sind schon vorgekommen:

    - Tuner 2 "tot"

    - Tuner 1 und 2 "tot"

    - Tuner 1 Empfang aber kein Bild


    Ich werde das weiter beobachten. Leider ist es nicht definiert reproduzierbar, man kann also nur auf den nächsten Fall warten.


    Grüße

    kamel5

    Kaum den Beitrag geschrieben und den neuen Treiberstand aktiviert, schon gibt es neue Logs.


    Diesmal war nur Live-TV aktiv und es hat wieder Tuner 2 getroffen, ab 14:39:13 und dann I2C transfer error ab 14:43:51.


    Bereinigte Logs vom Rechnerstart anbei.


    Grüße

    kamel5

    Hier noch ein aktuelles Beispiel:


    Wieder Tuner 2 ab

    Mär 14 10:56:04 vdr[3541]: [4874] frontend 1/0 timed out while tuning to channel 503 (RTL UHD), tp 111391

    und ab

    Mär 14 11:01:55 kernel: SAA716x FF 0000:0c:00.0: I2C transfer error, msg 0, addr = 0x60, len=2, flags=0x0, -ENXIO


    Mit dem aktualisierten Treiber scheint es bei mir häufiger aufzutreten. Allerdings trat es gestern nach einem VDR-Neustart mit Treiber neu laden den restlichen Tag nicht wieder auf. Das ist schon seltsam.


    Grüße

    kamel5

    Mache ich gern. Ich bin ja froh, das Du Dich um den Treiber kümmerst und ich dadurch ein recht unproblematisches Ausgabedevice nutzen kann.


    Ab jetzt ist auch der letzte Patch bei mir aktiv.

    Ich werde das weiter beobachten und melde mich wieder, wenn sich neue Erkenntnisse ergeben.


    Grüße

    kamel5

    VDR 2.6.6: ASUS Prime X470-PRO, Ryzen 7 5700X, 64GB, 6TB HD, GT1030, Fedora 39 Kernel 6.8 X86_64, Devicebonding 2 x 1 auf 2, TT6400, DVBSky S952 V3

    Git-Repo: gitlab.com/kamel5

    Es gibt neue Logs.


    Die erste Fehlermeldung des VDR ist jetzt eine Andere:

    Mär 14 16:12:23 vdr[3526]: [4859] frontend 1/0 is not receiving transponder 111524 for channel 24 (WDR HD Aachen) - retuning


    Erst später kommt dann:

    Mär 14 16:39:55 vdr[3526]: [4859] frontend 1/0 timed out while tuning to channel 179 (ProSieben HD), tp 111464


    Grüße

    kamel5

    Och nö!


    Das erste war ein Fifo-Überlauf in der Bridge (mein Fehler), das ist jetzt ein Problem mit dem I2C-Gate im Demod (keine Ahnung warum). Wieso sehe ich sowas nicht, auf 2 verschiedenen Rechnern?


    Ich muss mal drueber nachdenken...


    Gruss,

    S:oren

    Vielleicht dauert das loggen zu lange und der nächste read/write kommt schon.

    Nein. Das Problem ist hier:


    - Read i2c gate control register

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 write transfer, addr=0x68 length=2

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0000> 0xf1

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0001> 0x2b

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 read transfer, addr=0x68 length=1

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <R 0000> 0x40

    - Set enable bit (0x80) and write back

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 write transfer, addr=0x68 length=3

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0000> 0xf1

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0001> 0x2b

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0002> 0xc0

    - Access tuner behind i2c gate

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 write transfer, addr=0x60 length=1

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0000> 0x05

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 read transfer, addr=0x60 length=1

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <R 0000> 0x01

    - Close i2c gate, start with reading register value

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 write transfer, addr=0x68 length=2

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0000> 0xf1

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0001> 0x2b

    -> set read address, all ok

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 read transfer, addr=0x68 length=1

    -> do actual register read, this fails with NAK, but this is not checked by demod i2c gate code

    - Write back modified register value (enable bit removed)

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: I2C 1 write transfer, addr=0x68 length=3

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0000> 0xf1

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0001> 0x2b

    Mär 14 16:12:00 kernel: SAA716x FF 0000:0c:00.0: <W 0002> 0x7a

    -> write back nonsense to i2c gate control register


    Und Tschüss...

    Einmal editiert, zuletzt von S:oren () aus folgendem Grund: s/clock gate/i2c gate/

    Ah, register lesen -> wert modifizieren (trash) -> zurückschreiben macht Unsinn.

Jetzt mitmachen!

Sie haben noch kein Benutzerkonto auf unserer Seite? Registrieren Sie sich kostenlos und nehmen Sie an unserer Community teil!

Benutzerkonto erstellen Anmelden