„Es dauert fünfzehn Sekunden" liess sich nicht beantworten

Zwischen dem Antippen und dem ersten Bild liegen drei Strecken: die
Schlüsselbildsuche, der Start von ffmpeg und das Warten auf das erste
Stück. Keine davon war irgendwo abzulesen — jede Erklärung wäre Raterei
gewesen.

Jetzt steht je Wiedergabe eine Zeile im Tagesprotokoll, mit den ersten
beiden Zeiten. Dauert das erste Stück länger als zwei Sekunden, kommt
eine zweite Zeile dazu. Eine Zeile je Wiedergabe ist kein Lärm; sie ist
genau das, wonach man im Protokoll sucht.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

server/src/Flaro.Api/Endpoints/StreamEndpoints.cs

@@ -259,7 +259,8 @@ public static class StreamEndpoints
 
         // **Die Playlist.** Sie wächst, während ffmpeg schreibt.
         app.MapGet("/api/v1/stream/{sitzung:guid}/index.m3u8", async (
-            Guid sitzung, HttpResponse antwort, Streamkoordinator koordinator, CancellationToken ct) =>
+            Guid sitzung, HttpResponse antwort, Streamkoordinator koordinator,
+            Tagebuch tagebuch, CancellationToken ct) =>
         {
             // **Diese Datei darf nie zwischengespeichert werden**, und das ist
             // kein Vorsichtsmass, sondern aus einem Fehler gelernt: der Film
@@ -301,7 +302,19 @@ public static class StreamEndpoints
                 // **Als Inhalt, nicht als Datei.** `Results.File` hängt
                 // `Last-Modified` an und lädt damit zum Zwischenspeichern ein.
                 if (Streamkoordinator.Playlist(jetzt.Ordner) is { } liste)
+                {
+                    // **Die zweite Hälfte der Wartezeit.** Die erste steht
+                    // beim Anlegen der Sitzung; hier steht, wie lange ffmpeg
+                    // danach bis zum ersten Stück gebraucht hat. Nur wenn es
+                    // auffällt — vier Zeilen je Wiedergabe wären Lärm.
+                    if (versuch >= 8)
+                    {
+                        tagebuch.Schreiben(
+                            $"Wiedergabe: erstes Stück nach {versuch * 250} ms.");
+                    }
+
                     return Results.Text(liste, "application/vnd.apple.mpegurl", Encoding.UTF8);
+                }
 
                 // **Hört ffmpeg auf, ohne ein Segment geschrieben zu haben**,
                 // kommt auch keines mehr. Weiterzuwarten hiesse, eine halbe

server/src/Flaro.Api/Streamkoordinator.cs

@@ -166,9 +166,11 @@ public sealed class Streamkoordinator(
         // bleiben zusammen. Umgekehrt wäre es ein schlechter Tausch: einen
         // Sprungpunkt auf die Millisekunde zu treffen, ist zu viel verlangt.
         var gewuenscht = Math.Max(0, ab);
+        var uhr = System.Diagnostics.Stopwatch.StartNew();
         var gemeldet = plan.BildKopieren
             ? await schluesselbilder.DavorAsync(datei.Path, gewuenscht, ct)
             : gewuenscht;
+        var suche = uhr.ElapsedMilliseconds;
 
         var anfrage = new Stromanfrage(
             datei.Path, ordner, gelesen, plan, tonspur, gewuenscht, Hardware(), stufe, tonversatz);
@@ -184,10 +186,20 @@ public sealed class Streamkoordinator(
         var abbruch = new CancellationTokenSource();
         _sitzungen[kennung] = new Eintrag(sitzung, prozess, abbruch);
 
-        log.LogInformation(
-            "Strom {Kennung}: {Art} von {Datei} ab {Ab}s{Hoehe}.",
-            kennung, plan.Art, Path.GetFileName(datei.Path), sitzung.Ab,
-            plan.Hoehe is { } h ? $", auf {h}p" : "");
+        // **Mit Zeiten, und auch im Tagesprotokoll.**
+        //
+        // „Es dauert fünfzehn Sekunden" liess sich nicht beantworten: zwischen
+        // dem Antippen und dem ersten Bild liegen die Schlüsselbildsuche, der
+        // Start von ffmpeg und das erste Segment, und keine dieser Strecken
+        // war irgendwo abzulesen. Eine Zeile je Wiedergabe ist kein Lärm —
+        // sie ist genau das, wonach man im Protokoll sucht.
+        var meldung =
+            $"Wiedergabe: {plan.Art} von {Path.GetFileName(datei.Path)} ab {sitzung.Ab:0.#}s"
+            + (plan.Hoehe is { } h ? $", auf {h}p" : "")
+            + $" — Schlüsselbildsuche {suche} ms, Vorbereitung {uhr.ElapsedMilliseconds} ms.";
+
+        log.LogInformation("Strom {Kennung}: {Meldung}", kennung, meldung);
+        tagebuch.Schreiben(meldung);
 
         return sitzung;
     }