sectionsd: Handbremse los...

[ingrid]

Vielleicht möchte einer der Betroffenen dieses Diff gegen das aktuelle CVS testen.

Neuer sectionsd ist gebaut, werde das gleich mal auf die Box schicken und beobachten. Danke schonmal! ;-)

P.S. Wenn mir jemand zeigt, wie ich hier 'nen Anhang reinpacke, würde ich den sectionsd gerne zur Verfügung stellen. Ich finde den Upload-Button aber leider nicht...

[jmittelst]

...

P.S. Wenn mir jemand zeigt, wie ich hier 'nen Anhang reinpacke, würde ich den sectionsd gerne zur Verfügung stellen. Ich finde den Upload-Button aber leider nicht...

http://forum.tuxbox-cvs.sourceforge.net ... ght=upload

cu
Jens

[ingrid]

Danke Jens! Ich hab mal bei CarstenW einen Account beantragt.

Bis dahin gibt's hier 'nen compilierten sectionsd: <siehe Uploadlink>

(Evtl. kann ja jemand das auf den Upload-Server schieben, bis ich 'nen Account habe... Rapidshare ist immer so.... naja, Ihr wisst schon. ;-))

Edit: Ist jetzt im Upload: http://ulc.tuxbox-cvs.sourceforge.net/i ... y=Binaries&

[seife]

Ich habe mal versucht, das mit haufenweise printf's zu debuggen. Mir scheint es so, daß die threads in dmxEIT.change(), aufgerufen von verschiedenen commands, ganz oben am lock() hängen. Es dauerte öfters mehrere sekunden, diesen lock() zu bekommen, und ich vermute, daß es unter ungünstigen umständen zu einem deadlock kommt.
Typischerweise tritt das auf, wenn der Current-event fehlt. Besonders gut sehe ich das auf CNN Int. auf Astra 19.2E

Dummerweise bin ich im Fach pthread nicht wirklich fit :-(
Achso, der Diff hat für mich nichts verändert.

[ingrid]

Hier ein neues Log.

Folgendes ist passiert: sectionsd gestartet (also komplett jungfräulich, Box steht auf "Parlamentsfernsehen", die momentan keinen EPG senden), von "Parlamentsfernsehen" auf "rbb Berlin" geschaltet. Um 8:30 morgens war dort auf rbb EPG nur ab 19.30 verfügbar und die Box wurde wieder langsam. Vor/zurückzappen auf rbb brachte dann nach einem Moment "Kein EPG verfügbar" (auf rbb) als Popup. (EPG ist aber vorhanden - Kontrollbox ist ok.)
Das ist das, was das in diesem Post gelinkte Log enthält.

Auch für mich hat der diff scheinbar nichts verändert. Ich hatte mit dem Posten gewartet, bis mir mal wieder was auffällt. Die Box war die letzten Tage nicht wirklich in Benutzung, deshalb erst jetzt ein Report. Das Log ist mit dem letzten diff von Nirvana (1245fix1).

[Nirvana]

Nö, gegen das Verhalten hatte ich noch nix unternommen. Ich habe nur gegen das Freezen/abstürzen gekämpft, so wie es im letzten Log war. Hier sieht sectionsd ja noch gesund aus.

[ingrid]

Nö, gegen das Verhalten hatte ich noch nix unternommen. Ich habe nur gegen das Freezen/abstürzen gekämpft, so wie es im letzten Log war. Hier sieht sectionsd ja noch gesund aus.

Stimmt, hattest Du ja schon geschrieben. Freezes sind bei mir nicht mehr aufgetreten, der Part scheint (bei mir) also behoben zu sein, benutze die Box schon den ganzen Tag.

[dbluelle]

Auf meiner Dreambox stürzt Neutrino (auf CNN) auch immer noch ab und zu ab

Allerdings ist mir da folgendes aufgefallen:
Auf CNN wird der aktuelle EPG-Event nicht gefunden
=> in infoviewer.cpp (ca. Zeile 420) wird nach jeweils 1.1 Sekunden die Funktion getEPG aufgerufen, um den aktuellen Event auszulesen, Dadurch wird ein neuer Event an den sectionsd geschickt.
Da aber (bei CNN) eine Menge "dmx.read timeout"-Meldungen im sectionsd kommen,
vermute ich, daß durch die Timeouts der sectionsd länger als die 1.1 Sekunden beschäftigt ist und sich dadurch die Events so langsam "aufstauen", was dann irgendwann zum Absturz führt.

IMHO liegt der Fehler also an den dmx.read-Timeouts.
Das könnte evtl. mit dem von Obi im "Neutrino auf Dreambox"-Thread http://tuxbox-forum.dreambox-fan.de/for ... c&start=60 beschriebenen Problem zusammenhängen:

im CVS log habe ich folgende Änderung gesehen:

Code: Alles auswählen

--- a/apps/tuxbox/neutrino/daemons/sectionsd/sectionsd.cpp      29 Mar 2007 15:43:32 -0000      1.237
+++ b/apps/tuxbox/neutrino/daemons/sectionsd/sectionsd.cpp      17 May 2007 21:14:47 -0000
@@ -5919,7 +5919,9 @@ int eit_set_update_filter(int *fd)
        dsfp.filter.mask[1] = 0xFF;
        dsfp.filter.mask[2] = 0xFF;
        dsfp.filter.mask[3] = (0x1F << 1) | 0x01;
+#if HAVE_DVB_API >= 3
        dsfp.filter.mode[3] = 0x1F << 1;
+#endif
 //     dsfp.filter.mask[4] = 0xFF;
        dsfp.flags = DMX_CHECK_CRC | DMX_IMMEDIATE_START;
        dsfp.pid = 0x12;

Das kann einfach nicht richtig sein. Deshalb habe ich mir mal den umliegenden Code angeschaut und dabei ist mir etwas aufgefallen:

Code: Alles auswählen

	bzero(&dsfp, sizeof(struct dmx_sct_filter_params));
	dsfp.filter.filter[0] = 0x4e;	/* table_id */
	dsfp.filter.filter[1] = (unsigned char)(messaging_current_servicekey >> 8);
	dsfp.filter.filter[2] = (unsigned char)messaging_current_servicekey;
//	dsfp.filter.filter[3] = (messaging_current_version_number << 1) | 0x01;
//	dsfp.filter.filter[4] = messaging_current_section_number;
	dsfp.filter.mask[0] = 0xFF;
	dsfp.filter.mask[1] = 0xFF;
	dsfp.filter.mask[2] = 0xFF;
	dsfp.filter.mask[3] = (0x1F << 1) | 0x01;
#if HAVE_DVB_API >= 3
	dsfp.filter.mode[3] = 0x1F << 1;
#endif
//	dsfp.filter.mask[4] = 0xFF;

Durch den Aufruf von bzero wird u.a. filter[3] auf 0 gesetzt. Da das setzen von filter[3] auf einen sinnvollen Wert abgeschaltet ist, führt mask[3] mit dem Wert 0x3F dazu, dass niemals korrekte Daten empfangen werden können. Das hat zwei Ursachen:

1. Das niedrigste Bit hat folgende Bedeutung:

current_next_indicator: This 1-bit indicator, when set to "1" indicates that the sub_table is the currently applicable
sub_table. When the bit is set to "0", it indicates that the sub_table sent is not yet applicable and shall be the next
sub_table to be valid.

Daraus folgt, dass nur diejenigen Tabellen gültige Werte beinhalten, bei denen dieses Bit auf 1 steht. Der Code filtert jedoch ausschließlich auf 0.

2. Die fünf benachbarten Bits geben die Versionsnummer der Tabelle an:

version_number: This 5-bit field is the version number of the sub_table. The version_number shall be incremented
by 1 when a change in the information carried within the sub_table occurs. When it reaches value 31, it wraps around to
0. When the current_next_indicator is set to "1", then the version_number shall be that of the currently applicable
sub_table. When the current_next_indicator is set to "0", then the version_number shall be that of the next applicable
sub_table.

In der neueren API-Version gibt es das Mode-Feld, das die Bedeutung der Angegeben Bits im Filter umkehrt:

Eine Section / Tabelle wird dann an sectionsd weitergereicht, wenn für alle Bits des Filters gilt:

(filter AND mask) = (data AND mask) XOR mode

Es gibt keine entsprechende Funktion in der alten API.

Der Code für API >= 3 würde hier auf Versionen != 0 filtern, wenn Punkt 1 nicht zutreffen würde. Der Code für API < 3 macht nun das Gegenteil: Er filtert ausschließlich auf Version 0. Jedoch gilt hier ebenfalls Punkt 1.

Ich habe schon ein wenig mit den verschiedenen Werten für die Filter rumgespielt, aber noch keinen Erfolg gehabt

dbluelle

[seife]

Wobei der von obi monierte code nur aufgerufen wird, wenn sectionsd ohne "-nu" aufgerufen wird - mit "-nu" funktioniert es aber auch nicht besser.

Auf der dbox sehe ich das auch, aber halt weniger drastisch. Ich vermute daß (durch den schnelleren Prozessor) auf der dream die Race-condition um den lock() in dmxEIT.change(), siehe mein post weiter oben, leichter getriggert wird. Das sind aber alles Vermutungen meinerseits, der sectionsd ist für mich eher ein Buch mit sieben Siegeln ;-)

Ein sicheres Zeichen dafür, daß der sectionsd das problem hat ist bei mir, daß der sonst im Sekundentakt blinkende Punkt in der Uhrzeit (Infobar) gar nicht oder sehr unregelmäßig blinkt.

[Nirvana]

Auf CNN wird kein current Event gefunden, weil der table 0x4e buggy ist. Nämlich eine Stunde zu früh.
Das sectionsd allerdings deshalb in Probleme rennt ist nicht ok. Das Verhalten ist schon wie von dbluelle beschrieben.
Sollte aber bei allen früheren sectionsd Versionen auch so auftreten...

[seife]

Ja, als ich anfing das zu debuggen habe ich mein altes backup vom ~20.5. eingespielt, und das war nun auch kaputt. Damals war mir das nicht aufgefallen, weil ich mit anderen Problemen des dream-neutrino-ports kämpfte :-)

Es tritt aber auch auf anderen Kanälen auf, solange noch nach dem current-Event gesucht wird, nur nicht so drastisch, da das current-event irgendwann gefunden wird oder dann "kein EPG verfügbar" kommt, bevor neutrino abschmiert.
Erkennbar ist es schön am unregelmäßigen blinken des Uhrzeit-Doppelpunkts.

[Nirvana]

Gut, weil hier gerne alte und neue Bugs durcheinander geworfen werden.

Code: Alles auswählen

	if(evt.getName().empty() && flag !=0)
	{
		dmxEIT.change( 0 );
	}

Dann nehmt mal bitte testweise diese Zeilen raus. Sie veranlassen das Neustarten, wenn kein Current Event da ist. Das ist meines Erachtens gar nicht mehr notwendig, seit Houdini den update_eit bei jedem Eventwechsel eingeführt hat.
Aber bitte lasst meinen 1245fix nicht weg. Der wird auch benötigt.

[ingrid]

Code: Alles auswählen

	if(evt.getName().empty() && flag !=0)
	{
		dmxEIT.change( 0 );
	}

Dann nehmt mal bitte testweise diese Zeilen raus. Sie veranlassen das Neustarten, wenn kein Current Event da ist. Das ist meines Erachtens gar nicht mehr notwendig, seit Houdini den update_eit bei jedem Eventwechsel eingeführt hat.

Und hier für alle zum Testen der compilierte sectionsd mit Nirvana's Testfix. Ich habe das Ding der Übersicht halber mal "1245fix2" genannt.

Download sectionsd1245fix2.tar.gz

Damit nicht's beim Testen durcheinander geht (Sorry dafür, sowas kann echt nerven, ich weiß...) und nicht aneinander vorbei geredet wird:
Worauf genau zielt dieser "Fix 2"? Locks (Fix 1) und Slowdowns (Fix 2)? Nur damit keine Misverständnisse aufkommen und die Reports genauer werden...

[ingrid]

...entweder ich bin noch nicht richtig wach, oder mit dem Fix2 ist beim sectionsd der Nachbrenner gezündet worden. Jedenfalls sehe ich die Events beim Zappen früher (falls vorher noch kein EPG im Speicher ist) als mit Fix1 und Pre-Fix1. Sekunden-Blinken der Uhr ist regelmässig, Ein-/Ausfaden wirkt auch flüssiger.

Täusche ich mich da? Momentan sieht's nach 'nem wirklichen Fortschritt aus, ich werde das mal beobachten.

Ich hoffe, ich werfe nicht schon wieder die Symptome durcheinander...

[seife]

Bei mir (dream 500) sieht es auch besser aus.
Umschalten auf CNN int.: meist sofortiges Erscheinen der Infobar, mit sofortigem regelmäßigen Blinken des Sekundenpunkts.
Umschalten auf AL JAZEERA ENG (Astra 19.2E, 11508MHz): Es dauert ca 6.5 Sekunden, bis die Infobar da ist und weitere 6.5 Sek bis der Doppelpunkt zu blinken anfängt. Danach keine weiteren Beschwerden.

(Wenn ihr euch nun fragt, warum ich so komische Sender gucke: die sind einfach in der Reihenfolge
Deluxe Music
CNN Int.
AL JAZEERA ENG
Bloomberg TV Germany
in meiner Kanalliste, und ein Test den ich immer mache ist "der Reihe nach alle durchzappen")

Das scheint noch nicht die endgültige Lösung zu sein, aber als workaround ist es schon mal sehr gut. Und nachdem ganz neutrino ja eine Anhäufung von Workarounds ist... ;-)

[new.life]

also bei mir funktioniert der upload von Ingrid auch sehr gut seit heute morgen...keine Lücken im EPG bisher!

[PauleFoul]

also bei mir funktioniert der upload von Ingrid auch sehr gut seit heute morgen...keine Lücken im EPG bisher!

dito

[mb405]

dito.bis jetzt sehr sauber hier.
nur manchmal(ganz selten) kann man beobachten, das wenn eine sendung läuft und kein epg da ist, und in 2minuten die neue sendung losgeht, das er den next-epg als current-epg nimmt, und next-epg dann fehlt. das passiert ganz selten.

[wittinobi]

huhu,
erster eindruck mit den letzten fixes, echt sauber bis jetzt.
mal noch den langzeittest abwarten, aber sieht wirklich mal wieder echt gut aus, meiner meinung nach.

mfg
wittinobi

[Rebel1]

Nach knapp 2 Tagen, und Nirvana`s Fixes habe ich auch keine Lücken mehr im EPG oder sonstige Nebenwirkungen.

[new.life]

sieht ja wirklich gut aus. Wäre schön, wenn der fix bald ins CVS wandert.

[Nirvana]

Nur mal für die Codearchäologen unter euch - die Zeilen, die jetzt als störend identifiziert wurden, sind schon verdammt lange im CVS:

http://cvs.tuxbox-cvs.sourceforge.net/c ... 0&r2=1.181

Und ja, sie haben den sectionsd seitdem behindert. Es fiel nur nicht direkt auf, weil er ohnehin ressourcenverschwendend programmiert war.

Langsam fällt mir gar kein Verbesserungspotential mehr ein.
Vielleicht noch den Code begradigen, aber sonst... naja, sucken tut er natürlich trotzdem noch.

[seife]

Das changelog damals sagt

workaround for radio epg

Wenn man nun wüßte, was damit gemeint war... (ausführliche Changelogs sind doch was wert, auch wenn sie manche nicht gern lesen)

[Nirvana]

Doch was das sollte ist mir schon klar. Z.B. bei Premiere Radio oder Xtramusic stehen die Musiktitel in den Currentevents. Die wechseln dementsprechend oft. Wenn man ? drückte, sollte möglichst der aktuelle Songtitel angezeigt werden.
Mit Houdinis Methode ist das aber exakt gelöst und der workaround somit überflüssig...

[ingrid]

sieht ja wirklich gut aus. Wäre schön, wenn der fix bald ins CVS wandert.

Naja, ich will ja nicht die Stimmung versauen, aber so ganz koscher ist das Ganze noch nicht. Vorhin hatte ich folgende Situation:

Bei einigen Sendern fehlte EPG völlig, auf anderen fehlte der Now-Event. Bei fast allen Sendern fehlten die Langtexte (btw, Langtexte scheinen öfters zu fehlen). "EPG neu laden" führte dann dazu, dass überall der EPG verschwunden war (logisch), dann aber nichts neues mehr geladen wurde. Wie immer in solchen Situationen lief das Logging nicht, daher habe ich das Ganze nicht in Log-Form.

Nicht den Kopf abreissen, Nirvana, ich weiß dass es mit Deinem Fix nichts zu tun hat, aber trotzdem gibt's da wohl noch ein wenig zu tun. Ich werfe mal wieder das Logging an, vielleicht erwische ich ja was Sinnvolles...

Nirvana's Fixes scheinen jedenfalls voll zu greifen, hatte ich ja schon weiter oben geschrieben. Also auf in die nächste Schlacht?