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

Joe_D · February 11, 2008 at 9:45 AM

Hallo,

ich verwende eine TT S-1401 Budget-Karte mit c'tVDR6.1 und selbstgebasteltem Kernel 2.6.24. Ich habe Bild und Ton, aber im Logfile steht immer was von:

saa7146_i2c_writeout [irq]: timed out waiting for end of xfer

Ausserdem erzeugt der saa7146 meiner Meinung nach Interrupts wie verrückt.

Ist obige Meldung nun ein Problem?

Das hier brachte mir nur die Erkenntnis, das die S-1401 ab einer bestimmten Kernel-Version (>2.6.20?) funktionieren solle, mehr aber nicht...

Gruß

Joe_D

dbrenken · February 11, 2008 at 10:49 AM

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)

Viele Grüße
Dirk

e9hack · February 11, 2008 at 4:46 PM

Quote

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

dbrenken · February 11, 2008 at 11:35 PM

Hi,
spannend zu lesen ... ich weiß ja nicht, ob es noch weitere i2c-Probleme gibt, die mit dem o.g. Patch nichts zu tun haben ... Fakt ist, das dieser Patch meine Kombi aus TT-S1401 plus xineliboutput wieder zum Leben erweckt hat. Siehe auch http://bugzilla.kernel.org/show_bug.cgi?id=9887 ...

Viele Grüße
Dirk

Dr. Seltsam · February 12, 2008 at 12:21 AM

Quote

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.

glasbaustein · February 12, 2008 at 12:01 PM

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

tecfreak · February 12, 2008 at 12:21 PM

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

sparkie · February 12, 2008 at 12:21 PM

Quote

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.

heisu · February 12, 2008 at 12:53 PM

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

e9hack · February 12, 2008 at 6:00 PM

Quote

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

Dr. Seltsam · February 12, 2008 at 7:11 PM

Quote

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

tecfreak · February 12, 2008 at 11:35 PM

Hallo,

jetzt habe ich nochmal ins syslog geschaut und folgendes vorgefunden:

Code

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)
...

Display More

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

UFO · February 13, 2008 at 5:45 PM

Quote
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.

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

tecfreak · February 15, 2008 at 12:52 AM

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: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)

Display More

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

UFO · February 16, 2008 at 11:04 AM

Quote
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.

Quote

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.

Quote

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.

Quote

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...

Quote

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?

Quote

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

e9hack · February 16, 2008 at 2:29 PM

Quote

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.

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

UFO · February 17, 2008 at 6:12 AM

Quote

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

Joe_D · February 17, 2008 at 9:17 PM

@dbrenken

Vielen Dank für den Tipp, damit hat es nun geklappt! Warum das so ist, keine Ahnung aber seit ich diese Treiberversion verwende funktioniert nun alles.

Die Meldung kommt zwar immer noch aber nur wenn ich auf einem Kanal keinen Empfang habe (bzw. das SAT-Kabel ausgesteckt ist).

Gruß

Joe_D

Participate now!