[Patch] Mehr Informationen bei "ERROR: cTimer::Matches()"

MarkusE · January 30, 2026 at 4:25 PM

Mit dem attachten Patch werden bei "ERROR: cTimer::Matches()" Meldungen mehr Daten ausgegeben, was die Fehlersuche erleichtert.

kls , könntest Du das bitte übernehmen?

Könntest Du bitte außerdem in "abs(t - time(NULL)) > 10" die erlaubte Zeit von 10 auf 60 hochsetzen? Wir hatten das bereits diskutiert, bei mir brauchen die Festplatten manchmal etwas länger zum Anlaufen.

kls · February 1, 2026 at 12:49 PM

cTimer::Matches(time_t...) sollte nur mit der aktuellen Zeit aufgerufen werden (oder 0, dann wird diese intern ermittelt). Falls irgendwo Matches() nicht mit der aktuellen, sondern einer anderen Zeit aufgerufen werden soll, dann sollte dafür cTimer::CalcStartStopTime() verwendet werden. Der Backtrace zeigt ja schon die Stelle an, an der das zu ändern wäre.

Quote from MarkusE

Könntest Du bitte außerdem in "abs(t - time(NULL)) > 10" die erlaubte Zeit von 10 auf 60 hochsetzen? Wir hatten das bereits diskutiert, bei mir brauchen die Festplatten manchmal etwas länger zum Anlaufen.

Das sollte dann aber an der Stelle gefixt werden, wo die Ursache liegt, und nicht durch ein größeres "Delta" überdeckt werden.

MarkusE · February 1, 2026 at 4:01 PM

> Das sollte dann aber an der Stelle gefixt werden, wo die Ursache liegt, und nicht durch ein größeres "Delta" überdeckt werden.

Wie gesagt, es liegt daran, dass mein Festplatten-Raid schläft und etwas länger zum Aufwachen braucht. Das ist die Ursache. Wie soll ich das fixen?

kls · February 1, 2026 at 4:34 PM

Ich meine natürlich schon in VDR. Irgendwo muss ja diese Zeit vergehen, wo auf die Platten gewartet wird.

MarkusE · February 1, 2026 at 5:08 PM

Quote from kls

cTimer::Matches(time_t...) sollte nur mit der aktuellen Zeit aufgerufen werden (oder 0, dann wird diese intern ermittelt). Falls irgendwo Matches() nicht mit der aktuellen, sondern einer anderen Zeit aufgerufen werden soll, dann sollte dafür cTimer::CalcStartStopTime() verwendet werden. Der Backtrace zeigt ja schon die Stelle an, an der das zu ändern wäre.

Das stimmt natürlich alles. Trotzdem helfen zusätzliche Informationen bei der Fehlersuche. Und es kann ja nicht schaden, diese Informationen im Fehlerfall auszugeben?

Siehe auch RE: VDR version 2.7.7 freigegeben .

Da habe ich die Informationen, die ohne diesen Patch ausgegeben werden, gepostet. Und es war schwierig, die Fehlerursache zu finden. Daher habe ich den Patch bei mir eingebaut, mit dem mehr Informationen ausgegeben werden. Das hat die Fehlersuche erleichtert.

MarkusE · February 12, 2026 at 11:53 AM

Quote from kls

Ich meine natürlich schon in VDR. Irgendwo muss ja diese Zeit vergehen, wo auf die Platten gewartet wird.

Ich habe das jetzt mal analysiert. Dazu habe ich diesen Patch RE: VDR version 2.7.7 freigegeben eingebaut, mit verkürzter zulässiger Zeit.

Aus dem Syslog:

Code

2026-02-12T05:08:27.012781+01:00 rpi4s vdr: [3393840] ERROR: lock kept too long (27 seconds)                                                                   
2026-02-12T05:08:27.615979+01:00 rpi4s vdr: [3393840] /usr/bin/vdr cRecordControl::cRecordControl(cDevice*, cTimers*, cTimer*, bool) calling ?? at ??:0        
2026-02-12T05:08:27.616072+01:00 rpi4s vdr: [3393840] /usr/bin/vdr cRecordControls::Start(cTimers*, cTimer*, bool) calling ?? at ??:0                          
2026-02-12T05:08:27.616162+01:00 rpi4s vdr: [3393840] /usr/bin/vdr main calling ?? at ??:0                                                                     
2026-02-12T05:08:27.616275+01:00 rpi4s vdr: [3393840] /lib/aarch64-linux-gnu/libc.so.6 at libc-start.c:74                                                      
2026-02-12T05:08:27.616362+01:00 rpi4s vdr: [3393840] /lib/aarch64-linux-gnu/libc.so.6 __libc_start_main calling call_init at libc-start.c:128 at __libc_start_main_impl at libc-start.c:347                                                                                                                                  
2026-02-12T05:08:27.616441+01:00 rpi4s vdr: [3393840] /usr/bin/vdr _start calling ?? at ??:0

cRecordControl lockt SCHEDULES, d.h. SCHEDULES ist 27 Sekunden gelockt.

Dann wartet die Hauptschleife in vdr.c auf SCHEDULES:

Code

                    if (Timer->HasFlags(tfVps)) {                                                                                                                                                
                       if (Timer->Matches(Now, Setup.VpsMargin))                                                                                                                                 
                          InVpsMargin = true;                                                                                                                                                    
                       else if (Timer->Event()) {                                                                                                                                                
                          LOCK_SCHEDULES_READ;                                                                                                                                                   
                          InVpsMargin = Timer->Event()->StartTime() <= Now && Now < Timer->Event()->EndTime();                                                                                   
                          NeedsTransponder = Timer->Event()->StartTime() - Now < VPSLOOKAHEADTIME * 3600 && !Timer->Event()->SeenWithin(VPSUPTODATETIME);                                        
                          }                                                                                                                                                                      
                       else {                                                                                                                                                                    
                          LOCK_SCHEDULES_READ;                                                                                                                                                   
                          const cSchedule *Schedule = Schedules->GetSchedule(Timer->Channel());                                                                                                  
                          InVpsMargin = !Schedule; // we must make sure we have the schedule                                                                                                     
                          NeedsTransponder = Schedule && !Schedule->PresentSeenWithin(VPSUPTODATETIME);                                                                                          
                          }                                                                                                                                                                      
                       }                                                                                                                                                                         
                    else                                                                                                                                                                         
                       NeedsTransponder = Timer->Matches(Now, TIMERLOOKAHEADTIME);

Display More

D.h. die Hauptschleife wartet bis zu 27 Sekunden auf den Lock.

Damit ins abs(Now - time(NULL)) in der Hauptschleife 27 Sekunden.

kls · February 12, 2026 at 1:20 PM

Heißt das, es dauert 27 Sekunden, bis deine Platten hochlaufen?

Sind das zufällig solche hier?

cRecordControl::cRecordControl() lockt zwar Schedules, aber auch nur zum Lesen, genau wie die Hauptschleife. Diese sollte also da nicht warten müssen.

msv · February 12, 2026 at 2:12 PM

Quote from kls

Sind das zufällig solche hier?

Erinnert an meine Zuse Z23 Zeiten, an der ich damals noch ALGOL68 gelernt habe. Da gabs auch einen 8k Trommelspeicher, der nach dem Einschalten immer 2Std braucht um stabil zu laufen, damit wir mit unseren Lochstreifen uns dann in die Warteschlange (man konnte FIFO-Theorie life nachvollziehen) der vor einem stehenden Studenten einreihen konnten. Wenn dann wieder mal so ein Dödel aus versehen den Notaus (war ja so schön rot) gedrückt hatte, war der Labor Praxis Vormittag (immer Samstags) gelaufen.

Also 27sec sind doch nix...

SHF · February 13, 2026 at 1:40 AM

Quote from kls

Heißt das, es dauert 27 Sekunden, bis deine Platten hochlaufen?

Meine 5400er WD Red brauchen gefühlt eine Ewigkeit.

Eben gestoppt: time ls /mount/hdd1 -> real 0m6.889s
Und da ging es eher flott.

Bei einem Raid, wenn die Platten nacheinander starten sind die 27 Sekunden also nicht mal unrealistisch.

MarkusE · February 13, 2026 at 9:17 PM

Ich habe noch ein paar mehr debug Meldungen eingebaut. Das ganze ist deutlich einfacher als ich dachte.

Es hängt an if (MakeDirs(fileName, true)) in menu.c:5591 / cRecordControl::cRecordControl(cDevice *Device, cTimers *Timers, cTimer *Timer, bool Pause)

Gerufen von menu.c:5786 / bool cRecordControls::Start(cTimers *Timers, cTimer *Timer, bool Pause) : RecordControls[i] = new cRecordControl(device, Timers, Timer, Pause);

Gerufen von vdr.c:1144 / main(int argc, char *argv[]) : if (!cRecordControls::Start(Timers, Timer))

Das MakeDirs(fileName, true) braucht bei mir so zwischen 17 und 27 Sekunden, wenn die raid Festplatten geweckt werden müssen.

Also keine Blockade durch andere Threads wie ich erst dachte. Sonder einfaches a ruft b, b ruft c, und c ruft MakeDirs was 17-27s dauert ...

kls · February 13, 2026 at 11:11 PM

Also kein Handlungsbedarf meinerseits, oder?

MarkusE · February 14, 2026 at 7:01 AM

Quote from kls

Also kein Handlungsbedarf meinerseits, oder?

Wie bereits in #1 geschrieben:

Quote

Könntest Du bitte außerdem in "abs(t - time(NULL)) > 10" die erlaubte Zeit von 10 auf 60 hochsetzen? Wir hatten das bereits diskutiert, bei mir brauchen die Festplatten manchmal etwas länger zum Anlaufen.

kls · February 14, 2026 at 3:34 PM

Damit würde aber die Hauptschleife immer noch 27 Sekunden lang blockiert, was für den Benutzer auch nicht schön ist. Wäre sowas hier eine Möglichkeit?

Diff

--- vdr.c       2026/02/09 22:30:51     5.25
+++ vdr.c       2026/02/14 14:30:27
@@ -195,6 +195,47 @@
   exit(1);
 }

+class cSpinUpDisk : public cThread {
+private:
+  static time_t lastSpinUpDiskCheck;
+  static cSpinUpDisk spinUpDisk;
+  virtual void Action(void) override;
+public:
+  cSpinUpDisk(void);
+  static void Check(time_t Now);
+  };
+
+time_t cSpinUpDisk::lastSpinUpDiskCheck = 0;
+cSpinUpDisk cSpinUpDisk::spinUpDisk;
+
+cSpinUpDisk::cSpinUpDisk(void)
+:cThread("spin up disk")
+{
+}
+
+void cSpinUpDisk::Action(void)
+{
+  SpinUpDisk(cVideoDirectory::Name());
+}
+
+void cSpinUpDisk::Check(time_t Now)
+{
+  if (Now - lastSpinUpDiskCheck > 60) {
+     if (!spinUpDisk.Active()) {
+        int Delta = -1;
+        {
+          LOCK_TIMERS_READ;
+          if (const cTimer *Timer = Timers->GetNextActiveTimer())
+             Delta = Timer->StartTime() - Now;
+        }
+        if (Delta > 0 && Delta <= 60) {
+           spinUpDisk.Start();
+           }
+        }
+     lastSpinUpDiskCheck = Now;
+     }
+}
+
 int main(int argc, char *argv[])
 {
   // Save terminal settings:
@@ -1086,6 +1127,8 @@
            }
         if (Now - LastChannelChanged >= Setup.ZapTimeout && LastChannel != PreviousChannel[PreviousChannelIndex])
            PreviousChannel[PreviousChannelIndex ^= 1] = LastChannel;
+        // Spin up disk:
+        cSpinUpDisk::Check(Now);
         {
           // Timers and Recordings:
           static cStateKey TimersStateKey;

Display More

Das lagert den eigentlichen Vorgang in einen separaten Thread aus und sorgt rechtzeitig dafür, dass die Platten beim Start des Timers laufen. Die '60' kann man bei Bedarf auch konfigurierbar machen, aber ich denke mal, eine Minute sollte für alle Fälle genug sein.

MarkusE · February 14, 2026 at 7:51 PM

Der Patch sieht gut aus. Ich habe ihn mal bei mir eingebaut und werde testen

kls · February 14, 2026 at 9:50 PM

Etwas nachgebessert, damit auch wirklich mindestens 60 Sekunden vor dem Timer-Start der SpinUp gemacht wird:

Diff

--- vdr.c       2026/02/09 22:30:51     5.25
+++ vdr.c       2026/02/14 20:28:43
@@ -195,6 +195,40 @@
   exit(1);
 }

+class cSpinUpDisk : public cThread {
+private:
+  static time_t lastSpinUpDiskCheck;
+  static cSpinUpDisk spinUpDisk;
+  virtual void Action(void) override { SpinUpDisk(cVideoDirectory::Name()); }
+  cSpinUpDisk(void): cThread("spin up disk") {}
+public:
+  static void Check(time_t Now);
+  };
+
+time_t cSpinUpDisk::lastSpinUpDiskCheck = 0;
+cSpinUpDisk cSpinUpDisk::spinUpDisk;
+
+#define SPINUPDISK_TIME 60 // seconds between checks
+
+void cSpinUpDisk::Check(time_t Now)
+{
+  if (Now - lastSpinUpDiskCheck >= SPINUPDISK_TIME) {
+     lastSpinUpDiskCheck = Now;
+     if (!spinUpDisk.Active()) {
+        int Delta = -1;
+        {
+          LOCK_TIMERS_READ;
+          if (const cTimer *Timer = Timers->GetNextActiveTimer())
+             Delta = Timer->StartTime() - Now;
+        }
+        if (Delta > 0 && Delta <= 2 * SPINUPDISK_TIME) { // 2* to make sure we check at least SPINUPDISK_TIME before timer start
+           spinUpDisk.Start();
+           lastSpinUpDiskCheck += Delta; // to avoid double checks for the same timer start
+           }
+        }
+     }
+}
+
 int main(int argc, char *argv[])
 {
   // Save terminal settings:
@@ -1086,6 +1120,8 @@
            }
         if (Now - LastChannelChanged >= Setup.ZapTimeout && LastChannel != PreviousChannel[PreviousChannelIndex])
            PreviousChannel[PreviousChannelIndex ^= 1] = LastChannel;
+        // Spin up disk:
+        cSpinUpDisk::Check(Now);
         {
           // Timers and Recordings:
           static cStateKey TimersStateKey;

Display More

kls · February 15, 2026 at 11:16 AM

Was mir noch eingefallen ist: diese Änderung hilft nur bei Timern, die weit genug in der Zukunft liegen. Bei einem neu angelegten Timer, der sofort loslaufen soll, dauert es trotzdem 27 Sekunden, in denen das Menü "eingefroren" ist.

MarkusE · February 15, 2026 at 5:54 PM

Quote from kls

Was mir noch eingefallen ist: diese Änderung hilft nur bei Timern, die weit genug in der Zukunft liegen. Bei einem neu angelegten Timer, der sofort loslaufen soll, dauert es trotzdem 27 Sekunden, in denen das Menü "eingefroren" ist.

Um das zu lösen, könnte man MakeDirs() und Recording.WriteInfo() von cRecordControl::cRecordControl nach cRecorder schieben.

Der in cRecordControl::cRecordControl angegeben Grund:

Code

     Recording.WriteInfo(); // we write this *before* attaching the recorder to the device, to make sure the info file is present when the recorder needs to update the fps value!

erscheint mir nicht zwingend: Der cRecorder könnte doch ganz am Anfang MakeDirs() und Recording.WriteInfo() selbst aufrufen.

kls · February 15, 2026 at 9:37 PM

Nach MakeDirs() wird cStatus::MsgRecording(device, Recording.Name(), Recording.FileName(), true) aufgerufen. Ein Status-Plugin kann zurecht erwarten, dass das Directory von Recording.FileName() zu dem Zeitpunkt bereits existiert. Würde MakeDirs() erst (verzögert) im cRecorder aufgerufen, wäre das u.U. nicht der Fall, wenn es 27 Sekunden dauern kann, bis die Platten aktiv sind.

MarkusE · February 16, 2026 at 4:34 PM

Dann könnten wir cStatus::MsgRecording(device, Recording.Name(), Recording.FileName(), true) auch nach cRecorder verlegen.

Was ist besser (bzw. schlechter)?

Der Anwender wartet 27s bis er die Nachricht erhält, dass die Aufnahme startet (kann in der Zeit aber VDR bedienen)
Der Anwender wartet 27s bis er die Nachricht erhält, dass die Aufnahme startet (kann in der Zeit aber VDR nicht bedienen)

SHofmann · February 16, 2026 at 4:50 PM

Quote from MarkusE

Der Anwender wartet 27s bis er die Nachricht erhält, dass die Aufnahme startet (kann in der Zeit aber VDR nicht bedienen)

So etwa geht meines Erachtens überhaupt nicht. Eine halbe Minute, in der man nicht weiß, ober der VDR gerade abstürzt oder nur auf das Anlaufen einer Disk wartet?

Ich habe bei allen meinen Disks deshalb den Idle-Spin-Down sicherheitshalber abgeschaltet.

Participate now!