Deadlock bei Aufnahme auf letztverfügbarem Gerät mit Umschalten

    Hallo zusammen,


    nachdem das Lock-Problem mit Markad vermutlich (siehe [markad] überarbeiteter Decoder) gelöst ist, tritt nun eine Race-Condition / Deadlock unter folgenden Bedingungen auf:


    1. VDR zeigt Programm A

    2. VDR zeichnet auf Programm B auf

    3. VDR startet weitere Aufnahme auf (ggf. notwendig) verschlüsseltem Programm, für das A umgeschaltet werden muß


    Die Situation ist reproduzierbar (liegt aber möglicherweise an einem Patch :) )


    Letzte Log-Einträge ("Umschalt"-Timer per Live Plugin gesetzt):


    Backtrace


    ("gdb info threads" im nächsten Post)


    Was muß ich machen, um die Ursache zu finden?


    Stefan

    gdb info threads 1 - 29 :)


    gdb info threads 30 ...


    Arbeiten wir uns mal durch den Backtrace:


    menu.c:5705 in bool cRecordControls::Start(cTimers *Timers, cTimer *Timer, bool Pause)

    Code
    cDevice *device = cDevice::GetDevice(Channel, Priority, false);
if (device) {
   dsyslog("switching device %d to channel %d %s (%s)", device->DeviceNumber() + 1, Channel->Number(), *Channel->GetChannelID().ToString(), Channel->Name());


    Das "switching" unterbleibt, cDevice::GetDevice(Channel, Priority, false); kehrt vermutlich nicht zurück.


    Also weiter in device.c:359 hier cDevice *cDevice::GetDevice(const cChannel *Channel, int Priority, bool LiveView, bool Query)

    Code
    if (s->Device()) {
   if (s->Device() != d) {
      // CAM slot s is currently assigned to a different device than d
      if (Priority > s->Priority()) {
         if (!Query) {
            d->CamSlot()->Assign(NULL);
            s->Assign(d);
            }
         }


    Hier kehrt s->Assign(d); nicht mehr zurück, aus


    dvbdevice.c:2369 in void cDvbDevice::DetachAllReceivers(void)

    Code
    {
   cMutexLock MutexLock(&bondMutex);
   cDvbDevice *d = this;
   do {
       d->cDevice::DetachAllReceivers();
       d = d->bondedDevice;
       } while (d && d != this && needsDetachBondedReceivers);
   needsDetachBondedReceivers = false;
}


    DetachAllReceivers(void) scheint zumindest optisch Erfolg zu haben, also wieder nach device.c

    (To be continued)

    Den Sprung in ci.c und zurück schenken wir uns, letztlich bleibt der VDR dann (Backtrace #6) an einem LOCK_THREAD in device.c:450 hängen, wobei sich dieser wohl nicht locken läßt:


    device.c:450 in void cDevice::SetCamSlot(cCamSlot *CamSlot)

    Code
    void cDevice::SetCamSlot(cCamSlot *CamSlot)
{
   LOCK_THREAD;
   camSlot = CamSlot;
   scaMapper = CamSlot ? CamSlot->scaMapper : NULL;
   scaMapMasterSlot = scaMapper && CamSlot->IsMasterSlot() && !CamSlot->MtdActive();
}


    Das erklärt das Verhalten, aber nicht warum. Wenn der VDR bis in alle Ewigkeit wartet, sollte es also ein zweites LOCK_THREAD geben, das ihn gelockt hat. Jetzt kann man sich leider nicht darauf verlassen, das Klaus immer LOCK_THREAD benutzt (siehe Listen Lock mal per Statekey, mal per LOCK_XXX_READ), aber ein grep tut ja nicht weh...



    device.c -> wartet

    dvbplayer -> sollte Aufnahmen abspielen, inaktiv

    dvbsubtitle -> auch unwahrscheinlich, hat das PayTv nicht

    sections.c -> es klingelt was ...


    Gucken wir mal in section.c und finden das LOCK_THREAD in void cSectionHandler::Action(void)

    hier sections:196


    Da ist die if-Abfrage ( !on|| ...) nicht wirklich original, sondern entstammt einem Patch ...

    From: Klaus Schmidinger <vdr@tvdr.de>

    Date: Sun, 20 Jun 2021 10:27:19 +0200

    Subject: [PATCH] Improved responsiveness in cSectionHandler::Action()


    Das funktioniert wohl nur in 2.6.x, also erstmal raus damit, und nochmal von vorne.


    Stefan


    Hmm, spannend was Du da schreibst, lese neugierig mit. So ein (ähnliches) von Dir oben beschriebenes Verhalten habe ich tatsächlich bei mir auch (sporadisch) gesehen, aber ganz ohne Aufnahmen, nur beim intensiven hin und her schalten. Irgendwann Bild schwarz, aber VDR läuft ohne Ausgabe weiter. Dann entweder noch weiterzappen bis wieder was geht oder per femon und Taste "<"|">" auf einen anderen Tuner "springen lassen" ...


    Das mache ich immer intensiv nach Updates, bin gerade von 2.4.1 auf 2.4.7/2.4.8 auf meinem Haupt-VDR gesprungen und konnte das bisher nicht so wirklich richtig einsortieren.

    HowTo: APT pinning

    Das wäre ja nun wirklich zu einfach gewesen ... :)


    Die beiden vdr-2.5.x Patche, die den SectionHandler bearbeiteten, waren es nicht.

    Mit markad, epg2vdr, scraper2vdr und epgsearch tritt auch ohne der gleiche Effekt auf.

    Mit einer neuen Umschaltaufnahme, ARD, kein CI, passiert selbiges:



    gdb attach `pidof vdr`

    Code
    b__lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
103     ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S: Datei oder Verzeichnis nicht gefunden.
(gdb) bt
#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103
#1  0x00007fdcf5cb1714 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x558f420d5590) at ../nptl/pthread_mutex_lock.c:80
#2  0x0000558f4035c5a9 in cMutex::Lock (this=0x558f420d5590) at thread.c:224
#3  0x0000558f4035cd30 in cThread::Lock (this=<optimized out>) at thread.h:94
#4  cThreadLock::Lock (this=0x7ffd067943c0, Thread=<optimized out>) at thread.c:430
#5  0x0000558f402b9fdc in cDevice::SetCamSlot (this=0x558f420d5570, CamSlot=CamSlot@entry=0x0) at device.c:450


    Hmm. Exakt gleich?

    Man sollte das gebaute Packet vielleicht auch installieren ... :S

    (Immerhin wissen wir so: das CI ist maximal beim DSelect beteiligt)


    Später dann mehr,

    Stefan

    Jetzt weiß ich (noch) nicht, was genau klemmt(e), aber die beiden Kirschen scheinen das Timing im VDR signifikant zu verbessern.


    Mit Patchen:

    Code
    Jan  5 12:05:03 vdr: [4809] VAAPI: video: 10:53:48.489  +28 1000   0/\ms  48+3 v-buf
[..]
Jan  5 12:10:03 vdr: [4809] VAAPI: video: 10:58:48.489  +29 1129   0/\ms  80+3 v-buf
[..]
Jan  5 12:15:03 vdr: [4809] VAAPI: video: 11:03:48.489  +29  969   0/\ms  65+3 v-buf
[..]
Jan  5 12:20:03 vdr: [4809] VAAPI: video: 11:08:48.489  +28 1064   0/\ms  72+3 v-buf


    Ohne Patche:


    Gleicher Kanal ... "positive Schwingungen". :)

    Warum funktioniert der Patch (aus dem VDR-2.5)

    "Fixed flushing old data from the section handler"

    nun nicht im VDR-2.4.7+?


    Guckt man auf die Änderungen

    http://git.tvdr.de/?p=vdr.git;…b5eb8b46eeac04c63e3379118


    fällt zunächst auf, daß ein 100 ms Delay (cCondWait::SleepMs(100)) durch ein "bis zu" 100 ms Warten ersetzt wurde (poll mit timeout 100 o. 1000). Rauscht der VDR zu schnell durch, haben wir vielleicht schon den beobachteten den Salat.


    Also als Versuch ein Quickfix des Patches:

    Code
    -        if (poll(pfd, NumFilters, waitForLock ? 100 : 1000) > 0) {
+        if (poll(pfd, NumFilters, (!on || waitForLock) ? 100 : 1000) > 0) {
+    if (device->HasLock() == false)
+       cCondWait::SleepMs(100);


    Und taadaa, es funktioniert wieder. Ob vollständig und korrekt muß ich mal schauen. :)


    Naja. Irgendwas ist wohl noch - oder schlechtes Wetter:

    Code
    Jan  6 00:10:06 vdr: [21869] TS error #1 on PID 6522 (Continuity)
Jan  6 00:10:07 vdr: [21868] /srv/vdr/video/local/Die_Blonde_mit_entblößten_Brüsten/2022-01-05.22.10.10-0.rec: 1 error


    Stefan

    Leider tritt die Race-Condition auch ohne VDR-2.5.x Section-Handler-Patche auf. Daher habe ich mir das nochmal genauer angesehen. Vorgehen:


    a) Patche - zur leichteren Reproduzierbarkeit wieder eingebaut (ohne Delay)

    Nun trat der Fehler zunächst nicht auf. Liegt also doch eher nicht daran.


    b) Debugger starten (mit Text-UI, für Source)

    gdb attach `pidof vdr` -tui


    c) bt


    Nun stellt sich die Frage: Wer hat das Lock?

    Dazu im Backtrace die Zeile mit der Mutex (hier #2) suchen.

    Code
    (gdb) up 2
#2  0x0000561fcc646639 in cMutex::Lock (this=0x561fcd2fd630) at thread.c:224


    Dann Mutex-Besitzer ermitteln:

    Code
    (gdb) print mutex.__data.__owner
$1 = 7395


    Thread dazu suchen:

    Code
    (gdb) thread find 7395
Thread 40 has target id 'Thread 0x7ff5a4ff6700 (LWP 7395)'


    Zu Thread wechseln und Backtrace erstellen:


    Dann zur Stelle gehen, um die "Lockung" zu finden:

    Code
    (gdb) up 4
#4  0x0000561fcc5a7c3f in cDevice::Action (this=0x561fcd2fd610) at device.c:1701


    Dank Text-UI zeigt gdb die Source gleich an und man sieht:

    Code
    .│448     void cDevice::SetCamSlot(cCamSlot *CamSlot)
.│449     {
>│450    LOCK_THREAD;
.│451    camSlot = CamSlot;
.│452    scaMapper = CamSlot ? CamSlot->scaMapper : NULL;
.│453    scaMapMasterSlot = scaMapper && CamSlot->IsMasterSlot() && !CamSlot->MtdActive();
.│454     }


    Hängt durch dieses Lock in Zeile 1694 hier:


    Da weiß ich dann leider auch erstmal nicht weiter. (Screenshots des Debuggers anbei)

    Vielleicht haben Klaus kls oder HelmutB (VDR mit MTD-Patch) eine Idee?


    Stefan

    Wenn man nochmal genau guckt, stehen eigentlich beide Threads an einem:
    Thread 1: #0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103

    Thread 40: #0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:103


    Damit wäre dann die Frage, auf wenn wartet Thread 40?


    Also nochmal das Ganze, jedoch mit Prüfung, auf was Thread 40 wartet.

    Das Ergebnis überrascht nicht wirklich: er wartet auf Thread 1, der seine Mutex besitzt.


    Nur wo hat er die her? Die Suche liefert im Backtrace von Thread 1:

    #6 0x0000561fcc58ff12 in cCamSlot::Assign (this=0x561fe89809c0, Device=0x0, Query=<optimized out>) at ci.c:2546

    als nächst mögliche Stelle.


    Beim weiteren "up" lief der VDR dann weiter und machte einen Emergency Exit mit dem mir gut bekannten Fehler "ERROR: cStateKey::~cStateKey() called without releasing the lock first".


    Bliebe die Frage, warum wird eine der beiden Mutexe gelegentlich nicht freigegeben?


    Stefan

    Zu Testzwecken, das Blockierende LOCK_THREAD in cDevice::SetCamSlot(cCamSlot *CamSlot) (device.c:450)

    auskommentiert, weil es nur zwei Aufrufe dieser Funktion gibt, die bereits über ein Mutex-Lock verfügen.

    Bisher keine Auffälligkeiten.




    Das LOCK_THREAD entstammt einem Commit von Jan. 2014.

    http://git.tvdr.de/?p=vdr.git;…f4c3d522a341ed95057be6820

    "Improved locking for CAM slots and made the pure functions of cCiAdapter have default implementations"


    Da gab es Tage später einen Deadlock-Fix:

    http://git.tvdr.de/?p=vdr.git;…7be96417657a5bee70dae2c22

    "Fixed a deadlock"


    Vielleicht ist das Problem durch die vielen CI Änderungen in Folge wieder da?


    Grüße,

    Stefan


    Edit / Hinweis:

    Die zwei scaMap.. Zeilen entstammen den CAM-Tweaks.

    Hallo Fourty2,

    ich habe auch noch keine Erklärung, wie es zum Deadlock kommt.

    Faszinierend aber, welche Informationen du gdb entlocken kannst :) . Leider sind ein paar interessante Werte "optimized out".

    Etwas im deinem Post #12 ist mir unklar:

    Im 1. Backtrace von Device::SetCamSlot()

    Code
    #1  0x00007ff67808c714 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x561fcd2fd630) at ../nptl/pthread_mutex_lock.c:80
#2  0x0000561fcc646639 in cMutex::Lock (this=0x561fcd2fd630) at thread.c:224
#3  0x0000561fcc646dc0 in cThread::Lock (this=<optimized out>) at thread.h:94
#4  cThreadLock::Lock (this=0x7fff53955620, Thread=<optimized out>) at thread.c:430
#5  0x0000561fcc5a3fec in cDevice::SetCamSlot (this=0x561fcd2fd610, CamSlot=CamSlot@entry=0x0) at device.c:450

    und von cDevice::Action() in Thread 40

    Code
    #1  0x00007ff67808c714 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x561fcd2fff50) at ../nptl/pthread_mutex_lock.c:80
#2  0x0000561fcc646639 in cMutex::Lock (this=0x561fcd2fff50) at thread.c:224
#3  0x0000561fcc646d5f in cMutexLock::Lock (this=0x7ff5a4ff5dd0, Mutex=<optimized out>) at thread.c:404
#4  0x0000561fcc5a7c3f in cDevice::Action (this=0x561fcd2fd610) at device.c:1701

    Die beiden Mutexe sind doch unterschiedlich, d.h. von verschiedenen Threads - oder irre ich mich?

    HelmutB passed unfortunately away on July 21, 2022 ... RIP 🖤

    Hallo HelmutB ,


    ja sicher sind die Mutexe unterschiedlich:

    Thread 1 hat die Mutex A, auf die Thread 40 wartet.

    Thread 40 hat die Mutex B, auf die Thread 1 wartet.


    Wie beim Online-Neukundengeschäft:

    Der Verkäufer hat die Ware und will Vorkasse.

    Der Kunde das Geld und will erst nach Erhalt der Ware zahlen.Irgendwann schreitet dann eine Frau ein (VDR Watchdog) und will Geld und Ware, vorher tut sich nix.

    8)


    Die Optimierung (-march=native -O3, Quadcore) könnte man natürlich ausschalten, ob der Fehler dann noch auftritt, werde ich prüfen.


    Hab mal den Watchdog auf 10 Minuten gesetzt, damit ich per Zweitsystem den Debugger an laufen bekomme, sobald der VDR nicht mehr mag: immer diese Stelle bisher.


    Ohne LOCK_THREAD gab es bis jetzt (trotz der beiden VDR-2.5 Patche) keine Umschalt-Probleme mehr.


    Stefan

    Ok, soweit verstanden.

    Dass "cRecordControls::Start()->cDevice::GetDevice()->...Device::SetCamSlot()" von Thread 1 auf den Device-Thread warten müss ist klar, aber wann muss Thread 40 auf Thread 1 warten?

    Wenn Thread 1 der VDR MainThread ist, kann ein Lock darauf dann nicht nur über den MainThreadHook() von einem Plugin kommen ? Ich muss mir PLUGINS.html doch einmal durchlesen.

    LG Helmut

    HelmutB passed unfortunately away on July 21, 2022 ... RIP 🖤

    Das weiß ich auch nicht (hat Klaus aber 2014, VDR 2.1.x, so programmiert).


    Der VDR hing, nachdem der ListLock-Fehler im Markad Plugin (läuft im Hauptthread) beseitigt war, zuverlässig an dieser Stelle. Das tat er gelegentlich schon seit längerer Zeit (2.4.5 +/-). Bisher hatte ich das Modul in Verdacht, aber habe mal den Debuger angeklemmt.


    Der fand den VDR wartend, was erklärte, das alles, was im Haupthread mitlief (markad, Live, ...) hing, und anderes mit extra Thread halt weiter machte (vaapi - nur ohne Bild, epg2vdr, ..).


    Hab dann ermittelt, wer die Mutex besitzt - und etwas später, warum auch der Besitzer der Mutex wartete.

    Deadlock, klar. Hab dann geguckt, wo Thread 1 die Mutex holt und diese Warteposition von Thread 1 als erst einmal doppelten Mutexlock empfunden (und zunächst auskommentiert).


    Damit klappt dann natloses Umschalten zwischen Timern (A/B) und bei PID Update wieder. Allerdings scheint er mir jetzt gelegentlich beim Timerende zwei Gedenkminuten einzufügen - muß aber nicht zusammenhängen.


    (Reicht ja schon, das epg2vdr bei jeder Aufnahmeänderung (Neu, Ändern, Löschen) für ca 1,5 Minuten Channels und Recordings (und je Aufnahme kurz Schedules) readlockt, um alle 5000+ Aufnahmen durchzutackern und ein Plugin im Haupthread auf die Listen wartet.)


    Stefan

    HelmutB


    Hier nochmal der Deadlock mit -ggdb -O0, wegen Größe komplett als Textdatei anbei.


    Format dann jeweils Sourceausschnitt (soweit vorhanden), lokale Variablen, mutex:

    Code
    (gdb) up
#1  0x00007f2ce8ab9714 in __GI___pthread_mutex_lock (mutex=0x5652a3450870) at ../nptl/pthread_mutex_lock.c:80
(gdb) info locals
ignore1 = <optimized out>
ignore2 = <optimized out>
ignore3 = <optimized out>
type = <optimized out>
__PRETTY_FUNCTION__ = "__pthread_mutex_lock"
id = <optimized out>


    Und entsprechend für Thread 41:


    [..]


    HTH,

    Stefan

    Fourty2 :

    cDevice::Detach() kann in cDevice::Running() auch innerhalb von for (int i = 0; i < MAXRECEIVERS; i++) { } den Receiver aus der Liste entfernen, für das nachfolgende cDevice::SetCamSlot(NULL) muss aber immer auf das Ende der for-Schleife und das Unlock() gewartet werden.

    cMutexLock MutexLock(&mutexReceiver); in der for-Schleife hat sicher einen Performancegrund, in deinem Fall aber vielleicht irgendeinen Nebeneffekt, da Detach() halbfertig auf das Unlock() wartet.


    Kanst du testweise den mutexReceiver Lock() aus der Schleife herausholen:

    Helmut


    Wenn ich genauer darüber nachdenke, wird der Patch oben nichts verbessern, da sich cDevice::Runnng() den ThreadLock dann doch wieder vor Detach() holen wird.

    Also als Test gleich den ThreadLock in Detach(), ohne den Patch vom vorigen Post.

    Diff
    --- a/device.c.orig    2022-01-09 18:09:02.280144125 +0100
+++ b/device.c    2022-01-09 19:25:08.980216094 +0100
@@ -1823,6 +1823,7 @@ bool cDevice::AttachReceiver(cReceiver *
 
 void cDevice::Detach(cReceiver *Receiver)
 {
+  LOCK_THREAD;
   if (!Receiver || Receiver->device != this)
      return;
   bool receiversLeft = false;

    Das ist aber nicht als Lösung sondern nur als Test gedacht.

Participate now!

Don’t have an account yet? Register yourself now and be a part of our community!

Register Yourself Login