Measure analysis times

ConfusedPolarBear.Plugin.IntroSkipper.Tests/TestStatistics.cs

@@ -0,0 +1,22 @@
+using System;
+using System.Text.Json;
+using System.Text;
+using Xunit;
+
+namespace ConfusedPolarBear.Plugin.IntroSkipper.Tests;
+
+public class TestStatistics
+{
+    [Fact]
+    public void TestTSISerialization()
+    {
+        var expected = "\"TotalAnalyzedEpisodes\":42,";
+
+        var stats = new AnalysisStatistics();
+        stats.TotalAnalyzedEpisodes.Add(42);
+
+        var actual = Encoding.UTF8.GetString(JsonSerializer.SerializeToUtf8Bytes(stats));
+
+        Assert.Contains(expected, actual, StringComparison.OrdinalIgnoreCase);
+    }
+}

ConfusedPolarBear.Plugin.IntroSkipper/Configuration/configPage.html

@@ -105,6 +105,12 @@
                 </form>
             </div>
 
+            <details id="statistics">
+                <summary>Analysis Statistics</summary>
+
+                <pre id="statisticsText" style="font-size: larger"></p>
+            </details>
+
             <details id="visualizer">
                 <summary>Fingerprint Visualizer</summary>
 
@@ -187,6 +193,7 @@
 
             // settings elements
             var visualizer = document.querySelector("details#visualizer");
+            var statistics = document.querySelector("details#statistics");
             var btnEraseTimestamps = document.querySelector("button#btnEraseTimestamps");
 
             // visualizer elements
@@ -225,6 +232,42 @@
                 Dashboard.hideLoadingMsg();
             }
 
+            async function statisticsToggled() {
+                if (!statistics.open) {
+                    return;
+                }
+
+                // Blank any old statistics
+                const text = document.querySelector("pre#statisticsText");
+                text.textContent = "";
+
+                Dashboard.showLoadingMsg();
+
+                // Load the statistics from the server
+                let stats = await getJson("Intros/Statistics");
+
+                // Select which fields to print and label them with more friendly descriptions
+                let fields = "TotalCPUTime,FingerprintCPUTime,FirstPassCPUTime,SecondPassCPUTime,QuickScans,FullScans," +
+                    "TotalQueuedEpisodes";
+
+                let friendlyNames = {
+                    TotalCPUTime: "Total CPU time (ms)",
+                    FingerprintCPUTime: "Fingerprint time (ms)",
+                    FirstPassCPUTime: "First pass (ms)",
+                    SecondPassCPUTime: "Second pass (ms)",
+                    QuickScans: "Quick scans",
+                    FullScans: "Full scans",
+                    TotalQueuedEpisodes: "Episodes queued",
+                };
+
+                // Print all friendly names and data points
+                for (var f of fields.split(",")) {
+                    text.textContent += friendlyNames[f].padEnd(25) + stats[f] + "\n";
+                }
+
+                Dashboard.hideLoadingMsg();
+            }
+
             // show changed, populate seasons
             async function showChanged() {
                 clearSelect(selectSeason);
@@ -533,6 +576,7 @@
                 });
 
             visualizer.addEventListener("toggle", visualizerToggled);
+            statistics.addEventListener("toggle", statisticsToggled);
             txtOffset.addEventListener("change", renderTroubleshooter);
             selectShow.addEventListener("change", showChanged);
             selectSeason.addEventListener("change", seasonChanged);

ConfusedPolarBear.Plugin.IntroSkipper/Controllers/VisualizationController.cs

@@ -150,6 +150,17 @@ public class VisualizationController : ControllerBase
         return NoContent();
     }
 
+    /// <summary>
+    /// Returns the statistics for the most recent analysis.
+    /// </summary>
+    /// <response code="200">Analysis statistics.</response>
+    /// <returns>AnalysisStatistics.</returns>
+    [HttpGet("Statistics")]
+    public ActionResult<AnalysisStatistics> GetAnalysisStatistics()
+    {
+        return Plugin.Instance!.AnalysisStatistics;
+    }
+
     private string GetSeasonName(QueuedEpisode episode)
     {
         return "Season " + episode.SeasonNumber.ToString(CultureInfo.InvariantCulture);

ConfusedPolarBear.Plugin.IntroSkipper/Data/AnalysisStatistics.cs

@@ -0,0 +1,133 @@
+namespace ConfusedPolarBear.Plugin.IntroSkipper;
+
+using System;
+using System.Threading;
+using System.Text.Json;
+using System.Text.Json.Serialization;
+
+/// <summary>
+/// Detailed statistics about the last analysis operation performed. All times are represented as milliseconds.
+/// </summary>
+public class AnalysisStatistics
+{
+    /// <summary>
+    /// Gets the number of episodes that have been analyzed so far.
+    /// </summary>
+    public ThreadSafeInteger TotalAnalyzedEpisodes { get; } = new ThreadSafeInteger();
+
+    /// <summary>
+    /// Gets or sets the number of episodes that need to be analyzed.
+    /// </summary>
+    public int TotalQueuedEpisodes { get; set; }
+
+    /// <summary>
+    /// Gets the number of times a quick scan successfully located a pair of introductions.
+    /// </summary>
+    public ThreadSafeInteger QuickScans { get; } = new ThreadSafeInteger();
+
+    /// <summary>
+    /// Gets the number of times a full scan successfully located a pair of introductions.
+    /// </summary>
+    public ThreadSafeInteger FullScans { get; } = new ThreadSafeInteger();
+
+    /// <summary>
+    /// Gets the total CPU time spent waiting for audio fingerprints to be generated.
+    /// </summary>
+    public ThreadSafeInteger FingerprintCPUTime { get; } = new ThreadSafeInteger();
+
+    /// <summary>
+    /// Gets the total CPU time spent analyzing fingerprints in the initial pass.
+    /// </summary>
+    public ThreadSafeInteger FirstPassCPUTime { get; } = new ThreadSafeInteger();
+
+    /// <summary>
+    /// Gets the total CPU time spent analyzing fingerprints in the second pass.
+    /// </summary>
+    public ThreadSafeInteger SecondPassCPUTime { get; } = new ThreadSafeInteger();
+
+    /// <summary>
+    /// Gets the total task runtime across all threads.
+    /// </summary>
+    public ThreadSafeInteger TotalCPUTime { get; } = new ThreadSafeInteger();
+
+    /// <summary>
+    /// Gets the total task runtime as measured by a clock.
+    /// </summary>
+    public ThreadSafeInteger TotalTaskTime { get; } = new ThreadSafeInteger();
+}
+
+/// <summary>
+/// Convenience wrapper around a thread safe integer.
+/// </summary>
+[JsonConverter(typeof(ThreadSafeIntegerJsonConverter))]
+public class ThreadSafeInteger
+{
+    private int value = 0;
+
+    /// <summary>
+    /// Gets the current value stored by this integer.
+    /// </summary>
+    public int Value
+    {
+        get
+        {
+            return value;
+        }
+    }
+
+    /// <summary>
+    /// Increment the value of this integer by 1.
+    /// </summary>
+    public void Increment()
+    {
+        Add(1);
+    }
+
+    /// <summary>
+    /// Adds the total milliseconds elapsed since a start time.
+    /// </summary>
+    /// <param name="start">Start time.</param>
+    public void AddDuration(DateTime start)
+    {
+        var elapsed = DateTime.Now.Subtract(start);
+        Add((int)elapsed.TotalMilliseconds);
+    }
+
+    /// <summary>
+    /// Adds the provided amount to this integer.
+    /// </summary>
+    /// <param name="amount">Amount to add.</param>
+    public void Add(int amount)
+    {
+        Interlocked.Add(ref value, amount);
+    }
+}
+
+/// <summary>
+/// Serialize thread safe integers to a regular integer (instead of an object with a Value property).
+/// </summary>
+public class ThreadSafeIntegerJsonConverter : JsonConverter<ThreadSafeInteger>
+{
+    /// <summary>
+    /// Deserialization of TSIs is not supported and will always throw a NotSupportedException.
+    /// </summary>
+    /// <param name="reader">Reader.</param>
+    /// <param name="typeToConvert">Type.</param>
+    /// <param name="options">Options.</param>
+    /// <returns>Never returns.</returns>
+    public override ThreadSafeInteger? Read(ref Utf8JsonReader reader, Type typeToConvert, JsonSerializerOptions options)
+    {
+        throw new NotSupportedException();
+    }
+
+    /// <summary>
+    /// Serialize the provided TSI.
+    /// </summary>
+    /// <param name="writer">Writer.</param>
+    /// <param name="value">TSI.</param>
+    /// <param name="options">Options.</param>
+    public override void Write(Utf8JsonWriter writer, ThreadSafeInteger value, JsonSerializerOptions options)
+    {
+        writer.WriteNumberValue(value.Value);
+    }
+}

ConfusedPolarBear.Plugin.IntroSkipper/Plugin.cs

@@ -74,6 +74,11 @@ public class Plugin : BasePlugin<PluginConfiguration>, IHasWebPages
     /// </summary>
     public int TotalQueued { get; set; }
 
+    /// <summary>
+    /// Gets or sets the statistics from the most recent analysis run.
+    /// </summary>
+    public AnalysisStatistics AnalysisStatistics { get; set; } = new AnalysisStatistics();
+
     /// <summary>
     /// Gets the directory to cache fingerprints in.
     /// </summary>

ConfusedPolarBear.Plugin.IntroSkipper/ScheduledTasks/FingerprinterTask.cs

@@ -68,6 +68,11 @@ public class FingerprinterTask : IScheduledTask
     /// </summary>
     private Dictionary<Guid, ReadOnlyCollection<uint>> _fingerprintCache;
 
+    /// <summary>
+    /// Statistics for the currently running analysis task.
+    /// </summary>
+    private AnalysisStatistics analysisStatistics = new AnalysisStatistics();
+
     /// <summary>
     /// Initializes a new instance of the <see cref="FingerprinterTask"/> class.
     /// </summary>
@@ -137,14 +142,18 @@ public class FingerprinterTask : IScheduledTask
 
         // Include the previously processed episodes in the percentage reported to the UI.
         var totalProcessed = CountProcessedEpisodes();
-
         var options = new ParallelOptions()
         {
             MaxDegreeOfParallelism = Plugin.Instance!.Configuration.MaxParallelism
         };
 
+        var taskStart = DateTime.Now;
+        analysisStatistics = new AnalysisStatistics();
+        analysisStatistics.TotalQueuedEpisodes = Plugin.Instance!.TotalQueued;
+
         Parallel.ForEach(queue, options, (season) =>
         {
+            var workerStart = DateTime.Now;
             var first = season.Value[0];
 
             try
@@ -181,8 +190,14 @@ public class FingerprinterTask : IScheduledTask
             }
 
             progress.Report((totalProcessed * 100) / Plugin.Instance!.TotalQueued);
+
+            analysisStatistics.TotalCPUTime.AddDuration(workerStart);
+            Plugin.Instance!.AnalysisStatistics = analysisStatistics;
         });
 
+        analysisStatistics.TotalTaskTime.AddDuration(taskStart);
+        Plugin.Instance!.AnalysisStatistics = analysisStatistics;
+
         return Task.CompletedTask;
     }
 
@@ -292,7 +307,6 @@ public class FingerprinterTask : IScheduledTask
                 break;
             }
 
-            // TODO: add retry logic
             if (Plugin.Instance!.Intros.ContainsKey(lhs.EpisodeId) && Plugin.Instance!.Intros.ContainsKey(rhs.EpisodeId))
             {
                 _logger.LogTrace(
@@ -308,9 +322,9 @@ public class FingerprinterTask : IScheduledTask
                 _logger.LogTrace("Analyzing {LHS} and {RHS}", lhs.Path, rhs.Path);
 
                 var (lhsIntro, rhsIntro) = FingerprintEpisodes(lhs, rhs);
-
                 seasonIntros[lhsIntro.EpisodeId] = lhsIntro;
                 seasonIntros[rhsIntro.EpisodeId] = rhsIntro;
+                analysisStatistics.TotalAnalyzedEpisodes.Add(2);
 
                 if (!lhsIntro.Valid)
                 {
@@ -338,8 +352,12 @@ public class FingerprinterTask : IScheduledTask
         // Only run the second pass if the user hasn't requested cancellation and we found an intro
         if (!cancellationToken.IsCancellationRequested && everFoundIntro)
         {
+            var start = DateTime.Now;
+
             // Run a second pass over this season to remove outliers and fix episodes that failed in the first pass.
             RunSecondPass(season.Value);
+
+            analysisStatistics.SecondPassCPUTime.AddDuration(start);
         }
 
         lock (_introsLock)
@@ -358,8 +376,10 @@ public class FingerprinterTask : IScheduledTask
     /// <returns>Intros for the first and second episodes.</returns>
     public (Intro Lhs, Intro Rhs) FingerprintEpisodes(QueuedEpisode lhsEpisode, QueuedEpisode rhsEpisode)
     {
+        var start = DateTime.Now;
         var lhsFingerprint = Chromaprint.Fingerprint(lhsEpisode);
         var rhsFingerprint = Chromaprint.Fingerprint(rhsEpisode);
+        analysisStatistics.FingerprintCPUTime.AddDuration(start);
 
         // Cache the fingerprints for quicker recall in the second pass (if one is needed).
         lock (_fingerprintCacheLock)
@@ -389,6 +409,7 @@ public class FingerprinterTask : IScheduledTask
         Guid rhsId,
         ReadOnlyCollection<uint> rhsPoints)
     {
+        var start = DateTime.Now;
         var lhsRanges = new List<TimeRange>();
         var rhsRanges = new List<TimeRange>();
 
@@ -404,6 +425,7 @@ public class FingerprinterTask : IScheduledTask
         if (lhsRanges.Count == 0)
         {
             _logger.LogTrace("quick scan unsuccessful, falling back to full scan (±{Limit})", limit);
+            analysisStatistics.FullScans.Increment();
 
             (lhsContiguous, rhsContiguous) = ShiftEpisodes(lhsPoints, rhsPoints, -1 * limit, limit);
             lhsRanges.AddRange(lhsContiguous);
@@ -412,6 +434,7 @@ public class FingerprinterTask : IScheduledTask
         else
         {
             _logger.LogTrace("quick scan successful");
+            analysisStatistics.QuickScans.Increment();
         }
 
         if (lhsRanges.Count == 0)
@@ -421,6 +444,7 @@ public class FingerprinterTask : IScheduledTask
                 lhsId,
                 rhsId);
 
+            analysisStatistics.FirstPassCPUTime.AddDuration(start);
             return (new Intro(lhsId), new Intro(rhsId));
         }
 
@@ -442,6 +466,7 @@ public class FingerprinterTask : IScheduledTask
             rhsIntro.Start = 0;
         }
 
+        analysisStatistics.FirstPassCPUTime.AddDuration(start);
         return (new Intro(lhsId, lhsIntro), new Intro(rhsId, rhsIntro));
     }