[Gelöst] TT S-1401: timed out waiting for end of xfer (Kernel 2.6.24)

Zitat

Original von dbrenken
Hi,
das Problem ist als Regression von 2.6.24 bekannt und bereits in folgendem Repository gefixt:

http://linuxtv.org/hg/~hhackmann/v4l-dvb/ (changeset 7183)

Das i2c-Problem hat nichts mit dem Patch zu tun. Es scheint so, daß bei bestimmten Karten die Interrupts beim I2C-Transfer nicht richtig ausgelöst werden. Eigentlich ist nicht klar, ob nur die I2C-Interrupts betroffen sind. Es ist auch nicht klar, ob eine bestimmte Hardwarekonfiguration (shared Interrupts) das Problem auslöst. Man könnte den Transfer zurück auf Polling stellen. Man muß dann Teile von diesem Changset rückgängig machen.

Gruß
e9hack

Zitat

Original von e9hack
Man muß dann Teile von diesem Changset rückgängig machen.

das hatte bei mir (Probleme mit einer FuSi DVB-C FF) nichts gebracht.
Der Durchbruch kam, als ich noirqbalance als Kerneloption übergeben habe. (Eine gezielte smp_affinity für den IRQ der Karte hat nicht nachhaltig geholfen, es dauerte nur länger bis der Fehler auftrat)
nosmp bzw. ein Kernel ohne SMP-Unterstützung brachte ebenfalls fehelrfreien Betrieb.

Also ich habe genau die gleichen Meldungen auch mit der Kernelversion 2.6.22.

Mal ne blöde Frage, muss man jetzt bei dem neusten DiSEqC Patch von Hartmut Hackmann einen Parameter beim laden der Module übergeben um die Änderungen zu aktivieren, oder läuft alles wie gewohnt?

Habe wie dbrenken Probleme mit der S-1401 in einem xineliboutput System und es ist wie bei glasbaustein kernel 2.6.22.

Gruß
tec

Zitat

Originally posted by glasbaustein
Also ich habe genau die gleichen Meldungen auch mit der Kernelversion 2.6.22.

die Meldungen sehe ich auch schon seit Monaten:)

Mit 'linux-image-2.6.22-3-k7' aus 'www.backports.org'

Witzigerweise konnte ich aber noch keine offensichtlichen Auswirkungen erkennen, obwohl die betroffene Kiste
staendig im Einsatz ist. Darum habe ich mich noch nicht weiter um diese Baustelle gekuemmert.

Bei mir kommt die Meldung mit einer Haupauge Nova und einem selbstgebackenem 2.6.23. auf k7 Basis und hg treuibern. Seit neuestem mit einem 2.6.24-486
Ausser einer vollgemüllten dmesg keine erkennbaren Auswirkungen.
gruss
heiko

Zitat

Original von Dr. Seltsam

das hatte bei mir (Probleme mit einer FuSi DVB-C FF) nichts gebracht.

Wenn Du den I2C-Transfer auf Polling umstellst, kannst Du aber keine solche Fehlermeldung mehr erhalten haben:
saa7146_i2c_writeout [irq]: timed out waiting for end of xfer

Gruß
e9hack

Zitat

Original von e9hack
Wenn Du den I2C-Transfer auf Polling umstellst, kannst Du aber keine solche Fehlermeldung mehr erhalten haben:
saa7146_i2c_writeout [irq]: timed out waiting for end of xfer

hast recht, die Meldung war weg. Änderte aber nichts an regelmäßigen Crashes

Hallo,

jetzt habe ich nochmal ins syslog geschaut und folgendes vorgefunden:

vdr: [9305] switching to channel 43
vdr: [12934] transfer thread ended (pid=9305, tid=12934)
vdr: [12936] TS buffer on device 1 thread ended (pid=9305, tid=12936)
vdr: [12935] buffer stats: 0 (0%) used
vdr: [12935] receiver on device 1 thread ended (pid=9305, tid=12935)
vdr: [9305] buffer stats: 0 (0%) used
vdr: [12937] transfer thread started (pid=9305, tid=12937)
vdr: [12938] receiver on device 1 thread started (pid=9305, tid=12938)
vdr: [12939] TS buffer on device 1 thread started (pid=9305, tid=12939)
vdr: [9308] frontend 0 lost lock on channel 43, tp 111837
vdr: [9308] frontend 0 timed out while tuning to channel 43, tp 111837
vdr: [9308] frontend 0 regained lock on channel 43, tp 111837
vdr: [9305] switching to channel 44
vdr: [12937] transfer thread ended (pid=9305, tid=12937)
vdr: [12939] TS buffer on device 1 thread ended (pid=9305, tid=12939)
vdr: [12938] buffer stats: 84976 (4%) used
vdr: [12938] receiver on device 1 thread ended (pid=9305, tid=12938)
vdr: [9305] buffer stats: 21244 (1%) used
vdr: [12940] transfer thread started (pid=9305, tid=12940)
vdr: [12941] receiver on device 1 thread started (pid=9305, tid=12941)
vdr: [12942] TS buffer on device 1 thread started (pid=9305, tid=12942)
vdr: [12940] setting audio track to 1 (0)
kernel: [34335.063620] saa7146 (0) vpeirq: used 1 times >80%% of buffer (184428 bytes now)
kernel: [34365.024731] saa7146 (0) vpeirq: used 1 times >80%% of buffer (58656 bytes now)
kernel: [34424.926149] saa7146 (0) vpeirq: used 1 times >80%% of buffer (169388 bytes now)
...
vdr: [12940] cAudioRepacker(0xC1): skipped 120 bytes while syncing on next audio frame
vdr: [12940] PES packet shortened to 1778 bytes (expected: 2318 bytes)
vdr: [12940] cAudioRepacker(0xC0): skipped 300 bytes to sync on next audio frame
vdr: [12940] PES packet shortened to 1598 bytes (expected: 2318 bytes)
vdr: [12940] 2 cRepacker messages suppressed
vdr: [12940] cAudioRepacker(0xC1): skipped 48 bytes to sync on next audio frame
kernel: [34664.527057] saa7146 (0) vpeirq: used 1 times >80%% of buffer (184616 bytes now)
kernel: [34694.526414] saa7146 (0) vpeirq: used 1 times >80%% of buffer (181044 bytes now)
kernel: [34754.445431] saa7146 (0) vpeirq: used 1 times >80%% of buffer (177848 bytes now)
...
vdr: [12940] PES packet shortened to 1598 bytes (expected: 2318 bytes)
vdr: [12940] cAudioRepacker(0xC1): skipped 44 bytes while syncing on next audio frame
vdr: [12940] PES packet shortened to 3950 bytes (expected: 5390 bytes)
vdr: [12940] 1 cRepacker messages suppressed
vdr: [12940] cAudioRepacker(0xC0): skipped 96 bytes to sync on next audio frame
kernel: [35053.944789] saa7146 (0) vpeirq: used 1 times >80%% of buffer (156604 bytes now)
kernel: [35143.816328] saa7146 (0) vpeirq: used 1 times >80%% of buffer (184240 bytes now)
kernel: [35173.824003] saa7146 (0) vpeirq: used 1 times >80%% of buffer (156228 bytes now)
...
kernel: [36102.381962] saa7146_i2c_writeout: timed out waiting for end of xfer
...
kernel: [36102.390384] saa7146 (0) vpeirq: used 1 times >80%% of buffer (164124 bytes now)
kernel: [36222.261590] saa7146 (0) vpeirq: used 1 times >80%% of buffer (186684 bytes now)
kernel: [36252.227611] saa7146 (0) vpeirq: used 1 times >80%% of buffer (90992 bytes now)
...
vdr: [12940] PES packet shortened to 4130 bytes (expected: 5390 bytes)
vdr: [12940] cAudioRepacker(0xC0): skipped 272 bytes while syncing on next audio frame
vdr: [12940] PES packet shortened to 1598 bytes (expected: 2318 bytes)
vdr: [12940] 1 cRepacker messages suppressed
vdr: [12940] cAudioRepacker(0xC1): skipped 44 bytes while syncing on next audio frame
kernel: [36641.657142] saa7146 (0) vpeirq: used 1 times >80%% of buffer (184052 bytes now)
...

Eine Empfangsstörung liegt nicht vor, da femon keine BERs anzeigt und STR/SNR bei 80%/90% liegen. Bis dann irgendwann beim zappen ein "frontend lost lock" kommt. Da ich ein Monoblock LNB habe, hoffe ich, dass der DiSEqC Patch bei diesem Problem Abhilfe schafft.

Mir ist aber unklar, ob die dauernden Ton- und Bildaussetzer, die ca. 1-2 mal pro Minute kommen damit was zu tun haben.

Hat jemand einen Tipp?

Gruß
tec

Zitat

Original von tecfreak
Hallo,

jetzt habe ich nochmal ins syslog geschaut und folgendes vorgefunden:

Code

vdr: [9305] switching to channel 43
...
kernel: [34335.063620] saa7146 (0) vpeirq: used 1 times >80%% of buffer (184428 bytes now)
kernel: [34365.024731] saa7146 (0) vpeirq: used 1 times >80%% of buffer (58656 bytes now)
kernel: [34424.926149] saa7146 (0) vpeirq: used 1 times >80%% of buffer (169388 bytes now)
...

Eine Empfangsstörung liegt nicht vor, da femon keine BERs anzeigt und STR/SNR bei 80%/90% liegen. Bis dann irgendwann beim zappen ein "frontend lost lock" kommt. Da ich ein Monoblock LNB habe, hoffe ich, dass der DiSEqC Patch bei diesem Problem Abhilfe schafft.

Mir ist aber unklar, ob die dauernden Ton- und Bildaussetzer, die ca. 1-2 mal pro Minute kommen damit was zu tun haben.

Alles anzeigen

Dies ist ein ganz anderer Fehler!

Offenbar ist die Maschine nicht in der Lage, die Interrupts vom saa7146 schnell genug zu bearbeiten. Daher läuft der DMA-Buffer über, und es kommt zu den Aussetzern... (Iirc hatten wir das auf der ML schon mal in Verbindung mit SATA-Platten.)

Wahrscheinlich hilft es, budget-core mit Parameter "bufsize=1410" zu laden.

Was habt ihr alle nur für merkwürdige Hardware?

CU
Oliver

Hab es jetzt mal mit der option "bufsize=1410" probiert und es hat ein wenig geholfen. Die Tonaussetzer scheinen erstmal weg zu sein, was man auch im log sehen kann, da keine bytes mehr verworfen werden um zu synchronisieren.

Trotzdem scheint die buffer Nutzung ziemlich hoch zu sein, was sich jetzt aber etwas anders als zuvor im log bemerkbar macht.

Feb 15 00:01:21 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:01:21 PABLO vdr: [6649] buffer usage: 80% (tid=6648)
Feb 15 00:01:23 PABLO vdr: [6649] buffer usage: 90% (tid=6648)
Feb 15 00:01:23 PABLO vdr: [6648] clearing transfer buffer to avoid overflows
Feb 15 00:01:23 PABLO vdr: [6649] buffer usage: 0% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:19 PABLO vdr: [6649] buffer usage: 80% (tid=6648)
Feb 15 00:03:21 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:21 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:21 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:21 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:21 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:21 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:21 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:37 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:37 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:37 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:37 PABLO vdr: [6649] buffer usage: 60% (tid=6648)
Feb 15 00:03:37 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:39 PABLO vdr: [6649] buffer usage: 80% (tid=6648)
Feb 15 00:03:40 PABLO vdr: [6649] buffer usage: 90% (tid=6648)
Feb 15 00:03:40 PABLO vdr: [6648] clearing transfer buffer to avoid overflows
Feb 15 00:03:40 PABLO vdr: [6649] buffer usage: 0% (tid=6648)

Das System hat auch eine SATA Platte und das Mainboard ist ein GA-P35-DS3L. Würde es evtl. helfen wenn man dieses hier wieder rückgängig macht?

Den Beitrag in der linux-dvb ML habe ich jetzt auch gefunden.
In der aktuellen kernel config habe ich gerade gesehen, dass CONFIG_HZ auf 250 steht. Bringt es was, wenn ich das auf 1000Hz stelle?

Da wurde auch außerdem eine nvidia Karte als mögliche Fehlerquelle erwähnt. Hier läuft ebenfalls eine Nvidia 7600GS mit dem proprietären nvidia Treiber (169.07).

Die Budget DVB Karte macht auch mit keinem anderen Gerät IRQ sharing.
Bei dem System handelt es sich um ein Ubuntu 7.10 64bit mit einer Q6600 CPU und dem oben genannten Mainboard.

Langsam gehen mir die Ideen aus und ich kann mir irgendwie garnicht vorstellen, dass irgend ein anderes physisches Gerät für diese buffer underruns verantwortlich sein soll.

Gruß
tec

Zitat

Original von tecfreak
Hab es jetzt mal mit der option "bufsize=1410" probiert und es hat ein wenig geholfen. Die Tonaussetzer scheinen erstmal weg zu sein, was man auch im log sehen kann, da keine bytes mehr verworfen werden um zu synchronisieren.

Trotzdem scheint die buffer Nutzung ziemlich hoch zu sein, was sich jetzt aber etwas anders als zuvor im log bemerkbar macht.

Code

...
Feb 15 00:03:37 PABLO vdr: [6649] buffer usage: 70% (tid=6648)
Feb 15 00:03:39 PABLO vdr: [6649] buffer usage: 80% (tid=6648)
Feb 15 00:03:40 PABLO vdr: [6649] buffer usage: 90% (tid=6648)
Feb 15 00:03:40 PABLO vdr: [6648] clearing transfer buffer to avoid overflows
Feb 15 00:03:40 PABLO vdr: [6649] buffer usage: 0% (tid=6648)

Diese Meldung kommt von VDR, nicht vom Treiber. Sie bedeutet letztendlich, daß die Daten schneller hereinkommen als VDR sie loswerden kann.

Falls Fehler nur bei Aufnahme auftritt:
Festplattendurchsatz prüfen ("hdparm -tT /dev/...").

Andernfalls hängt es wohl an der Ausgabe über die Grafikkarte.

Zitat

Das System hat auch eine SATA Platte und das Mainboard ist ein GA-P35-DS3L. Würde es evtl. helfen wenn man dieses hier wieder rückgängig macht?

Kannst Du versuchen, imho jedoch eher nicht.

Zitat

Den Beitrag in der linux-dvb ML habe ich jetzt auch gefunden.
In der aktuellen kernel config habe ich gerade gesehen, dass CONFIG_HZ auf 250 steht. Bringt es was, wenn ich das auf 1000Hz stelle?

Unwahrscheinlich.

Zitat

Da wurde auch außerdem eine nvidia Karte als mögliche Fehlerquelle erwähnt. Hier läuft ebenfalls eine Nvidia 7600GS mit dem proprietären nvidia Treiber (169.07).

Tja...

Zitat

Die Budget DVB Karte macht auch mit keinem anderen Gerät IRQ sharing.
Bei dem System handelt es sich um ein Ubuntu 7.10 64bit mit einer Q6600 CPU und dem oben genannten Mainboard.

Huh - Jetzt werden schon VDRs mit Quadcore gebaut...
Ändert sich was, wenn Du den Kernel mal mit "nosmp" startest?

Zitat

Langsam gehen mir die Ideen aus und ich kann mir irgendwie garnicht vorstellen, dass irgend ein anderes physisches Gerät für diese buffer underruns verantwortlich sein soll.

Ein einziger Fehler an einer ungünstigen Stelle kann das ganze System ausbremsen.

CU
Oliver

Zitat

Original von UFO

Diese Meldung kommt von VDR, nicht vom Treiber. Sie bedeutet letztendlich, daß die Daten schneller hereinkommen als VDR sie loswerden kann.

Falls Fehler nur bei Aufnahme auftritt:
Festplattendurchsatz prüfen ("hdparm -tT /dev/...").

Andernfalls hängt es wohl an der Ausgabe über die Grafikkarte.

Alles anzeigen

Wie wird eigentlich die Bildsynchronisation beim Softdevice gemacht? Der MPEG-Datenstrom hat ja bei der Bildwiederhohlrate einen gewissen Jitter. Theoredisch könnte die Wiederholrate auch geringfügig unter bzw. über dem Nominalwert liegen. Bei FF-Karten wird da ja am Clock gedreht um Decoder und Wiederholrate synchron zu halten.

Gruß
e9hack

Zitat

Original von e9hack

Wie wird eigentlich die Bildsynchronisation beim Softdevice gemacht? Der MPEG-Datenstrom hat ja bei der Bildwiederhohlrate einen gewissen Jitter. Theoredisch könnte die Wiederholrate auch geringfügig unter bzw. über dem Nominalwert liegen. Bei FF-Karten wird da ja am Clock gedreht um Decoder und Wiederholrate synchron zu halten.

Gute Frage! Daran könnte es natürlich auch liegen.

CU
Oliver