Kaum durch den Compiler geschoben, schon veraltet ...
Deadlock bei Aufnahme auf letztverfügbarem Gerät mit Umschalten
-
-
Ja, leider.Und jetzt habe ich ein zweites Mal darüber nachgedacht und fürchte, der Erkenntnisgewinn wird sich in Grenzen halten. Das es mit einem CamSlot->Assign(NULL) ohne Wartezeit funktioniert hat dein Versuch ohne LOCK_THREAD ja schon gezeigt.
Gibt es das Problem ohne MTD auch (bei den camtweaks-Flags 0x4 dazunehmen) ?
Helmut
-
Der der VDR um 20:00 mit Umschalttimer (ohne VDR-2.5 Patch, abgesehen TS-Errors, mit original LOCK_THREAD) an seiner neuen Lieblingsstelle pausierte, hab ich den Patch oben kurz eingespielt:
Code
Display MoreJan 9 20:09:21 vdr: [4840] retuning due to modification of channel 101 Jan 9 20:09:21 vdr: [4840] switching to channel 101 Jan 9 20:09:21 vdr: [4840] SendCaPmts CAM 1: [1] actives in CAM: 2 -> 1 (3 pids) Jan 9 20:09:21 vdr: [4840] CAM 1: unassigned from device 1 Jan 9 20:09:21 vdr: [4840] CAM 1/1: reusing MTD CAM slot Jan 9 20:09:21 vdr: [5021] device 1 TS buffer thread ended (pid=4840, tid=5021) Jan 9 20:09:21 vdr: [5020] buffer stats: 259816 (0%) used Jan 9 20:09:21 vdr: [5020] device 1 receiver thread ended (pid=4840, tid=5020) Jan 9 20:09:21 vdr: [4840] CAM 1: assigned to device 1 Jan 9 20:09:21 vdr: [5057] device 1 receiver thread started (pid=4840, tid=5057, prio=high) Jan 9 20:09:21 vdr: [5058] device 1 TS buffer thread started (pid=4840, tid=5058, prio=high) Jan 9 20:09:21 vdr: [4840] SendCaPmts CAM 1: [0] actives in CAM: 1 -> 1 (3 pids) Jan 9 20:09:21 vdr: [4840] SendCaPmts CAM 1: [1] actives in CAM: 1 -> 2 (6 pids) Jan 9 20:09:21 vdr: [4840] VAAPI: video/vaapi: clear image Jan 9 20:09:22 vdr: [4962] frame error #1 (missing backref) Jan 9 20:09:22 vdr: [4962] /srv/vdr/video/local/#1/2022-01-09.18.20.100-0.rec: 1 error Jan 9 20:09:22 vdr: [5001] frame error #1 (missing backref) Jan 9 20:09:22 vdr: [4840] switching device 1 to channel 101 Jan 9 20:09:22 vdr: [4840] SendCaPmts CAM 1: [0] actives in CAM: 2 -> 2 (6 pids) Jan 9 20:09:23 vdr: [5001] /srv/vdr/video/local/#1/2022-01-09.20.00.100-0.rec: 1 error Jan 9 20:09:23 vdr: epg2vdr: Cleanup old symlinks Jan 9 20:09:24 vdr: [4905] VAAPI-ERROR: video/vaapi: black surface displayed Jan 9 20:09:24 vdr: [4905] VAAPI: video: --:--:--.--- +0 0 0/\ms 0+3 v-buf Jan 9 20:09:34 vdr: [4903] SVDRP < 192.168.1.2:45162 client connection accepted Jan 9 20:09:34 vdr: [4903] SVDRP > 192.168.1.2:45162 server created Jan 9 20:09:34 vdr: epg2vdr: Got epgd state 'busy (scraping)' (5) Jan 9 20:09:34 vdr: epg2vdr: Change handler state to 'standby' Jan 9 20:09:34 vdr: [4903] SVDRP < 192.168.1.2:45162 lost connection to client Jan 9 20:09:34 vdr: [4903] SVDRP < 192.168.1.2:45162 connection closed Jan 9 20:09:34 vdr: [4903] SVDRP < 192.168.1.2:45162 server destroyed Jan 9 20:09:36 vdr: scraper2vdr: Got 1 series, continuing... Jan 9 20:09:36 vdr: scraper2vdr: Got 744 new/updated Series in 26s from Database (new max scrsp: 1641744651) Jan 9 20:09:36 vdr: scraper2vdr: Loading Series content from Database... Jan 9 20:09:38 vdr: [4903] SVDRP < 192.168.1.2:45164 client connection accepted Jan 9 20:09:38 vdr: [4903] SVDRP > 192.168.1.2:45164 server created Jan 9 20:09:38 vdr: epg2vdr: Got epgd state 'standby' (1) Jan 9 20:09:38 vdr: epg2vdr: Change handler state to 'active' Jan 9 20:09:38 vdr: [4903] SVDRP < 192.168.1.2:45164 lost connection to client Jan 9 20:09:38 vdr: [4903] SVDRP < 192.168.1.2:45164 connection closed Jan 9 20:09:38 vdr: [4903] SVDRP < 192.168.1.2:45164 server destroyed Jan 9 20:09:51 vdr: scraper2vdr: Handled 16 of 744 series, continuing... Jan 9 20:10:06 vdr: [5001] frame error #751 (missed) Jan 9 20:10:06 vdr: [5001] /srv/vdr/video/local/#2/2022-01-09.20.00.100-0.rec: 750 errors Jan 9 20:10:06 vdr: [5001] ERROR: video data stream broken Jan 9 20:10:06 vdr: [5001] emergency exit request ignored according to setup
Beim Retune hat es dann das CAM abgeschossen, aber der VDR hing nicht.
Im Debugger sah man so nichts. Mit "c" nach automatischem Modulreset ging es dann weiter.
Debugger ist noch attached, gucke gegen 22:00, was bei einem Umschalttimer regulär passiert...
Edit:
CAM mag das gar nicht, VDR läuft weiter.
Am MTD (0x4) sollte es eigentlich nicht liegen, da ich den Deadlock auch mit FTA Programmen erzeugen kann. Aber wird probiert:
Edit 2:
Mit 6 Umschaltaufnahmen (FTA <-> FTA, 1x laufend über CAM) kam der Fehler nicht (LOCK_THREAD original), aber immer tut er das auch nicht (CAMTweaks = 0x827 statt 0x823).
Edit 3:
Bin erst einmal wieder auf
Diff
Display More--- a/device.c +++ b/device.c @@ -447,7 +447,7 @@ void cDevice::SetCamSlot(cCamSlot *CamSlot) { - LOCK_THREAD; +// LOCK_THREAD; camSlot = CamSlot; scaMapper = CamSlot ? CamSlot->scaMapper : NULL; scaMapMasterSlot = scaMapper && CamSlot->IsMasterSlot() && !CamSlot->MtdActive();
und CAM-Tweaks 0x823 zurück.
Bisher führte zu häufiges Umschlten auf CAM-Programmen dazu, daß irgendwann nur noch eine von zwei möglichen Entschlüsselungen verfügbar war. Jetzt machte das CAM nach 24x schnellem Umschalten während einer Aufnahme (über das CAM) einen Reset (CI+ Auth) und weiter geht's.
Code
Display MoreJan 9 22:43:09 vdr: [16543] SendCaPmts CAM 1: [1] actives in CAM: 2 -> 2 (6 pids) Jan 9 22:43:09 vdr: [16543] VAAPI: video: set trick-speed 0 Jan 9 22:43:09 vdr: [16555] VAAPI: audio/alsa: using pass-through device 'hdmi:CARD=PCH,DEV=2,AES0=0x06' Jan 9 22:43:09 vdr: [16555] VAAPI: audio/alsa: start delay 336ms Jan 9 22:43:10 vdr: [16556] DDCI-Err: can't write to CI adapter (/dev/dvb/adapter2/ca0): Eingabe-/Ausgabefehler Jan 9 22:43:11 vdr: [16556] DDCI-Err: can't write to CI adapter (/dev/dvb/adapter2/ca0): Eingabe-/Ausgabefehler Jan 9 22:43:11 vdr: [16556] DDCI-Err: can't write to CI adapter (/dev/dvb/adapter2/ca0): Eingabe-/Ausgabefehler Jan 9 22:43:12 vdr: [16556] CAM 1: module present ==> /var/log/syslog <== Jan 9 22:43:12 kernel: [54166.602621] dvb_ca_en50221: dvb_ca adapter 2: DVB CAM detected and initialised successfully ==> /var/log/vdr.log <== Jan 9 22:43:12 vdr: [16556] CAM 1: module ready
Stefan
-
Das scheint mir prinzipiell noch zu diesem Thread hier zu gehören:
-
Vielleicht kommt der Deadlock von cDevice::DetachAllReceivers.
Wenn Thread 1 bereits hier den Lock auf mutexReceiver hält, wird er in cDevice::Detach() nicht freigegeben. Und damit würde der Thread 41 in cDevice::Action() nicht aus der for-Schleife herauskommen und das Unlock() am Ende von while(Running() nie stattfinden.
Kommentiere einmal die MuteLock Zeile() in DetachAllReceivers aus.
Codevoid cDevice::DetachAllReceivers(void) { // cMutexLock MutexLock(&mutexReceiver); <<------- hier for (int i = 0; i < MAXRECEIVERS; i++) Detach(receiver[i]); }
Ich frage mich allerdings, wieso dann ein normales Umschalten von einem verschlüsseltem Sender funktioniert. Veilleichts liegt es an DDCI2.
Helmut
-
Mit der auskommentierten Zeile habe ich es jetzt noch nicht geschafft, einen Deadlock zu erzeugen.
Einmal hat das Modul in die bereits laufende Aufnahme ein paar Backref-Fehler gemacht, einmal die neue Aufnahme mit #750 TS-Fehler begonnen, bevor Bild kam. Aber kein Hänger mehr.
Seiteneffekt bisher (Kurztest, klar) nicht zu endecken. Habe aber auch nur zwei Tuner.
Stefan
-
Dann bin ich ziemlich sicher, dass der Deadlock hier ausgelöst wurde. Da durch DetachAllReceivers() alle Receiver auf "NULL" gesetzt werden, ist hier ein Lock auf die Receiverliste vermutlich auch nicht so wichtig.
Backref-Fehler sagt mir jetzt nichts. Die 750 TS-Fehler zu Beginn sind unverschlüsselten Pakete die man bei einem Programmwechsel zwangsläufig erhält. Es dauert etwas bis die erste ECM empfangen wird und das Modul mit der Entschlüsselung beginnen kann. Das ist im Live Modus nicht anders, ein Bild gibt es erst mit entschlüsselten TS-Paketen.
LG Helmut
-
Hatte angenommen, fehlende ECM (hier NDS alle 7 sec, ~ 300 ms vor Gültigkeit - falls das noch aktuell ist), würden als Scrambled im Log ankommen, aber stimmt, dann kommt nix, nur Modul abschießen macht "scrambled"-Fehler.
Backref: dies hier
Code
Display More+void cFrameChecker::CheckFrame(const uchar *Data, int Length) +{ + int64_t Pts = TsGetPts(Data, Length); + if (Pts >= 0) { + if (lastPts >= 0) { + int Diff = int(round((PtsDiff(lastPts, Pts) / double(frameDelta)))); + if (Diff > 0) { + if (Diff <= MAX_BACK_REFS) { + if (lastFwdRef > 1) { + if (backRefs != uint32_t((1 << (lastFwdRef - 1)) - 1)) + Report("missing backref");
Ich stopfe das ins VDR-Log, und gucke bei Fehlern schon mal nach, was Ursache war.
Stefan
-
In TsPostProcess() werden bei allen TS-Paketen die "scrambled"-Bits auf 0 gesetzt - unabhängig davon, ob es vom Modul zuvor tatsächlich entschlüsselt werden konnte. Dadurch erkennt man das leider nicht.
Helmut
-
Da durch DetachAllReceivers() alle Receiver auf "NULL" gesetzt werden, ist hier ein Lock auf die Receiverliste vermutlich auch nicht so wichtig.
Der mutexReceiver schützt die Liste der Receiver des Devices, sollte also bei jedem Zugriff gelockt werden. Den Lock in DetachAllReceivers() wegzulassen fühlt sich irgendwie nicht richtig an. Was wäre z.B. wenn die Schleife receiver[i] "nimmt" und bevor sie Detach() damit aufrufen kann von anderer Stelle ein explizites Detach() mit diesem Receiver gemacht (und der Receiver gelöscht) wird? Ich weiß nicht, wie wahrscheinlich dieses und andere Szenarien sind, aber den Lock hier wegzulassen würde mir Bauchschmerzen machen...
-
kls mit "nicht so wichtig", meinte ich eher, ein Weglassen des Lock auf mutexReceiver in DetachAllReceivers() hat wahrscheinlch weniger Nebenwirkungen als das auf den Device-mutex in SetCamSlot().
Der Aufruf von Detach() kann nur von außerhalb des "großen" mutexReceiver-Lock stattfinden. Wie wäre es, innerhalb eines kurzen Lock die *Receiver in ein lokale Kopie auzulesen und nach dem Lock das Detach() über die Kopie aufzurufen.
So in etwa:
Diff
Display More--- a/device.c 2021-07-02 08:58:59.000000000 +0200 +++ b/device.c 2022-01-14 20:11:37.673570204 +0100 @@ -1868,9 +1868,14 @@ void cDevice::DetachAll(int Pid) void cDevice::DetachAllReceivers(void) { + cReceiver *r[MAXRECEIVERS]; // local copy + { cMutexLock MutexLock(&mutexReceiver); for (int i = 0; i < MAXRECEIVERS; i++) - Detach(receiver[i]); + r[i] = receiver[i]; + } + for (int i = 0; i < MAXRECEIVERS; i++) + Detach(r[i]); } // --- cTSBuffer -------------------------------------------------------------
LG Helmut
-
Mein Vorschlag von zuvor hat ein anderes Problem - die lokale Kopie der Receiverliste kann nach dem Lock schnell veraltet sein. Das ist eigentlich auch nicht viel besser als ganz ohne Lock.
Wenn andere Threads die Receiverliste nur lesen ist es ja kein Problem, er wer könnte die Liste zeitgleich noch verändern wollen?
Helmut
-
Da der Deadlock nur wegen camSlot->Assign() entsteht, könnte man das in Detach() auch nur bedingt machen. Dann kann der große MutexLock(&mutexReceiver) bleiben.
Diff: device-Detach-CamSlotAssign.diff
Display More--- a/device.c 2021-07-02 08:58:59.000000000 +0200 +++ b/device.c 2022-01-14 23:09:15.637279056 +0100 @@ -1824,7 +1824,7 @@ bool cDevice::AttachReceiver(cReceiver * return false; } -void cDevice::Detach(cReceiver *Receiver) +void cDevice::Detach(cReceiver *Receiver, bool AssignCamSlot) { if (!Receiver || Receiver->device != this) return; @@ -1846,7 +1846,7 @@ void cDevice::Detach(cReceiver *Receiver if (camSlot) { if (Receiver->priority > MINPRIORITY) { // priority check to avoid an infinite loop with the CAM slot's caPidReceiver camSlot->StartDecrypting(); - if (!camSlot->IsDecrypting() && !camSlot->IsActivating()) + if (AssignCamSlot && !camSlot->IsDecrypting() && !camSlot->IsActivating()) camSlot->Assign(NULL); } } @@ -1868,9 +1868,13 @@ void cDevice::DetachAll(int Pid) void cDevice::DetachAllReceivers(void) { + { cMutexLock MutexLock(&mutexReceiver); for (int i = 0; i < MAXRECEIVERS; i++) - Detach(receiver[i]); + Detach(receiver[i], false); + } + if (camSlot && !camSlot->IsDecrypting() && !camSlot->IsActivating()) + camSlot->Assign(NULL); } // --- cTSBuffer ------------------------------------------------------------- --- a/device.h 2021-07-02 08:58:59.000000000 +0200 +++ b/device.h 2022-01-14 22:49:03.170569698 +0100 @@ -852,7 +852,7 @@ public: ///< Returns true if we are currently receiving. The parameter has no meaning (for backwards compatibility only). bool AttachReceiver(cReceiver *Receiver); ///< Attaches the given receiver to this device. - void Detach(cReceiver *Receiver); + void Detach(cReceiver *Receiver, bool AssignCamSlot = true); ///< Detaches the given receiver from this device. void DetachAll(int Pid); ///< Detaches all receivers from this device for this pid.
LG Helmut
-
Vielleicht eine Erklärung, warum dieser Deadlock nicht schon häufiger festgestellt wurde.
Die Vorrausetzungen sind: Live auf verschlüsseltem Sender mit dem einzigen Device das für eine Aufnahme zur Verfügung steht, ein Aufnahme-Timer für ein Programm auf einem anderen Transponder und zum Zeitpunkt des Timer-Start muss auch tatsächlich das Live-Progarmm aktiv sein.Die letzte Punkt ist der Interessante:
Der VDR will sicherstellen, das zum Zeitpunkt der Aufnahme ein Device tasächlich zur betriebsbereit ist. Dazu wird innerhalb der
TimervorlaufzeitTIMERLOOKAHEADTIME schon ein Device ausgewählt und mit diesem auf den Transponder getuned - aber nicht im "Liveview" Modus sondern nur mit IDLE-Priority. Da es sich dabei um das Device mit den verschlüsselten Live-Programm handelt, wird dabei auch der CamSlot entfernt.Der VDR main-Loop will aber immer einen Progarmm darstellen, also wird nach kurzer Zeit wieder auf das Live Programm zurückgeschalten. Das ganze wiederholt sich innerhalb der
TimervorlaufzeitTIMERLOOKAHEADTIME einige Male.Für den Deadlock ist entscheidend, welcher der beiden Zustände beim Timer-Start tatsächlich aktiv ist. Beim Live-Programm kommt ein Deadlock, beim Idle-Programm nicht.
Da insgesamt länger auf dem Idle-Transponder getuned ist, ist die Wahrscheinlichkeit eines Deadlock geringer als die einer erfolgreichen Aufnahme. Ich musste für zwei Deadlocks 6 Timer Programmieren.
Hier ein paar Zeilen aus dem syslog. 2min.
VorlaufzeitSetup.VpsMargin, Live ist "3sat HD", Aufnahme um 22:10 auf "ORF1 HD" - in diesem Fall kein Deadlock weil unmittelbar davor auf richtigen Transponder und ohne camslot getuned wird.Code
Display Morean 17 22:08:32 gentoo64vdr vdr[2876]: [2876] CAM 1: unassigned from device 2 Jan 17 22:08:32 gentoo64vdr vdr[2876]: [2876] switching device 2 to channel 920 T-8232-101-14101 (ORF1 HD) Jan 17 22:08:32 gentoo64vdr vdr[2876]: [2876] info: Aufnahme beginnt in Kürze! Jan 17 22:08:46 gentoo64vdr vdr[2876]: [2876] switching to channel 926 T-8232-501-14505 (3sat HD) Jan 17 22:08:46 gentoo64vdr vdr[2876]: [2876] CAM 1: assigned to device 2 Jan 17 22:08:53 gentoo64vdr vdr[2876]: [2876] CAM 1: unassigned from device 2 Jan 17 22:08:53 gentoo64vdr vdr[2876]: [2876] switching device 2 to channel 920 T-8232-101-14101 (ORF1 HD) Jan 17 22:08:53 gentoo64vdr vdr[2876]: [2876] info: Aufnahme beginnt in Kürze! Jan 17 22:09:07 gentoo64vdr vdr[2876]: [2876] switching to channel 926 T-8232-501-14505 (3sat HD) Jan 17 22:09:07 gentoo64vdr vdr[2876]: [2876] CAM 1: assigned to device 2 Jan 17 22:09:16 gentoo64vdr vdr[2876]: [2876] CAM 1: unassigned from device 2 Jan 17 22:09:16 gentoo64vdr vdr[2876]: [2876] switching device 2 to channel 920 T-8232-101-14101 (ORF1 HD) Jan 17 22:09:16 gentoo64vdr vdr[2876]: [2876] info: Aufnahme beginnt in Kürze! Jan 17 22:09:30 gentoo64vdr vdr[2876]: [2876] switching to channel 926 T-8232-501-14505 (3sat HD) Jan 17 22:09:31 gentoo64vdr vdr[2876]: [2876] CAM 1: assigned to device 2 Jan 17 22:09:38 gentoo64vdr vdr[2876]: [2876] CAM 1: unassigned from device 2 Jan 17 22:09:38 gentoo64vdr vdr[2876]: [2876] switching device 2 to channel 920 T-8232-101-14101 (ORF1 HD) Jan 17 22:09:38 gentoo64vdr vdr[2876]: [2876] info: Aufnahme beginnt in Kürze! Jan 17 22:09:52 gentoo64vdr vdr[2876]: [2876] switching to channel 926 T-8232-501-14505 (3sat HD) Jan 17 22:09:52 gentoo64vdr vdr[2876]: [2876] CAM 1: assigned to device 2 Jan 17 22:10:00 gentoo64vdr vdr[2876]: [2876] CAM 1: unassigned from device 2 Jan 17 22:10:00 gentoo64vdr vdr[2876]: [2876] switching device 2 to channel 920 T-8232-101-14101 (ORF1 HD) Jan 17 22:10:00 gentoo64vdr vdr[2876]: [2876] info: Aufnahme beginnt in Kürze! Jan 17 22:10:03 gentoo64vdr vdr[2876]: [2876] CAM 1: assigned to device 2 Jan 17 22:10:03 gentoo64vdr vdr[2876]: [2876] switching device 2 to channel 920 T-8232-101-14101 (ORF1 HD) Jan 17 22:10:03 gentoo64vdr vdr[2876]: [2876] timer 2 (920 2210-2300 VPS 'ZIB Nacht') start
Helmut
Was mir auffällt: dieses 2 Minuten lange Hin- und Herschalten sieht eigentlich nicht besonders gut aus :).
-
Also bisher funktioniert Dein letzter Patch ... Danke
Das 2 minütige Hin- und Herschalten macht das "VPS" schon immer.
Bei "normalen" Timer-Aufnahmen passiert das nur unsichtbar auf freien Karten.
VPS ist bei mir wegen epg2vdr aus, sonst brechen die Aufnahmen ab, sobald sie in der Datenbank sind.
Muß dem Plugin mal abgewöhnen, an aktiven VPS Timern rumzutogglen.
Stefan
-
Fourty2 : Ich habe es mit dem Patch gestern nicht mehr getestet, aber gut wenn du es bestätigen kannst.
Eine kleine Richtigstellung: Es ist natürlich nicht die Timervorlaufzeit sondern TIMERLOOKAHEADTIME (60s) bzw. Setup.VpsMargin (bei mir 120s) innerhalb der auf den Transponder der kommenden Aufnahme geschalten wird. Ich habe es in meinem Post richtiggestellt.
Helmut
-
Ich würde das dann so wie angehängt übernehmen. Bitte damit nochmal testen.
Im Prinzip könnte das Problem wohl auch in cDevice::DetachAll(int Pid) auftreten, daher habe ich dafür eine eigene Funktion eingeführt und rufe diese an den nunmehr drei Stellen auf.
Participate now!
Don’t have an account yet? Register yourself now and be a part of our community!