Beiträge von Fourty2

  • [SkinNopacity] Aktuelle Probleme

    Gerade ein Invalid Lock im Log gesehen - erstes Auftreten (nach GIT Pull um den 20.12.):

    Trat auf, als nach Abspielen einer Aufnahme Zwecks Marken-Edit, zurück auf Live-TV geschaltet wurde.


    Grüße,

    Stefan

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

    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.

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

    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

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

    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

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

    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

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

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

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

    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

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

    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


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

    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)

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

    gdb info threads 30 ...


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

    gdb info threads 1 - 29 :)


  • 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

  • [markad] überarbeiteter Decoder

    Hmm ... eigenwillig. Es klemmt, sobald beide Karten mit Aufnahmen belegt werden sollen


    - die zu startende Aufnahme startet nicht, nur das Live-Bild verschwindet

    - die (fünf Minuten später) zu beendende Aufnahme läuft weiter / Timer wird nicht gelöscht

    - VDR bleibt per Live bedienbar, aber Timerlöschung wird im VDR nicht bearbeitet.

    - Möglicherweise Deadlock mit der gleichen Funktion im epg2vdr, die bei VPS das Umschalten verhindert



    Gucke ich mir später ohne epg2vdr/scraper2vdr/epgsearch an.


    Stefan

  • [markad] überarbeiteter Decoder

    Zitat von kfb77

    Ich habe mal 2 Aufnahmen gleichzeitig auf meinem Testserver gestartet. epg2vdr Plugin, markad VPS an [..]

    Das glaube ich gerne. :)


    Hier waren es aber a) Kanäle ohne VPS und b) gibt's noch epgsearch oder c) vielleicht hab ich was in epg2vdr zerpatscht, als ich das auf die Non-Blocking-API umgebaut habe. Das muß ich erstmal selbst ausschließen.


    Stefan

  • [markad] überarbeiteter Decoder

    Prinzipiell funktioniert es, aber der VDR hat noch ein Problem. Denke, es war die im Markad aktivierte VPS Funktion, die epg2vdr zielsicher zerlegt...


    Log (TV auf 100, Aufnahmen 20:00 auf 101 und 104):

    Code
    Jan  4 19:59:26 vdr: [4731] switching device 2 to channel 101
Jan  4 19:59:37 vdr: [4731] switching device 2 to channel 104
Jan  4 19:59:48 vdr: [4731] switching device 2 to channel 101

    Das hat er mit Lock-Fehler nicht (mehr) gemacht.


    Dann normaler Start der ersten Aufnahme:


    Danach bleibt dann irgendwas hängen - die zweite Aufnahme startet nicht mehr.

    Code
    Jan  4 20:00:03 vdr: [4779] VAAPI: video: reset start
Jan  4 20:00:03 vdr: [4779] VAAPI: video: set clock --:--:--.---
Jan  4 20:00:03 vdr: [4731] VAAPI: video: set closing
Jan  4 20:00:03 vdr: [4731] VAAPI: video: set clock --:--:--.---
Jan  4 20:00:03 vdr: [4731] VAAPI: video: reset start
Jan  4 20:00:03 vdr: [4731] VAAPI: video: set clock --:--:--.---
Jan  4 20:00:03 vdr: [4779] VAAPI: video/vaapi: closing eof
Jan  4 20:00:03 vdr: [4731] SendCaPmts CAM 1: [1] actives in CAM: 2 -> 1 (3 pids)


    Umschalten erfolgt nicht mehr ... Ruhe ... Deadlock-ähnlich.

    Wiederholung mit gleichem Ergebnis.


    Habe jetzt das VPS im Markad deaktiviert, der VDR hat damit seine Nöte, wenn epg2vdr aktiv ist.


    Nächster Versuch läuft nachher ... werde berichten. :)


    Edit:

    1. Aufnahme (ohne Markad-VPS) startet normal, VDR noch ok.

    2. Aufnahme (überlappend) ok

    3. Mit Umschalten auf weitere Karte ... Aufnahme unterbleibt.



    Stefan

  • [markad] überarbeiteter Decoder

    Zitat von kfb77

    Ja, ist es. Soll ja auch nur feststellen, ob es wirklich genau an dem Lock liegt und das hoffentlich vor einem Crash. Wenn das funktioniert, können wir das Problem qualifizierter bei kls adressieren.

    Du hast gesehen, es gab nochmals einen Update vom Patch.

    Natürlich nicht. Aber ist ja ein Paket-VDR mit quilt-patchen, kein Beinbruch daher...


    Ergebnis wie vor - unter gleichen Bedingungen - weiter kam er nicht:


    42.

  • [markad] überarbeiteter Decoder

    Lange lebt er damit nicht ... der VDR. :-]

    (Selbst ganz ohne Aufnahme - das käme erst gegen 20:15)