From 3a4e688376824446b275e074b8a959cefa2576d4 Mon Sep 17 00:00:00 2001 From: ConfusedPolarBear <33811686+ConfusedPolarBear@users.noreply.github.com> Date: Mon, 4 Jul 2022 02:03:10 -0500 Subject: [PATCH] Measure analysis times --- .../TestStatistics.cs | 22 +++ .../Configuration/configPage.html | 44 ++++++ .../Controllers/VisualizationController.cs | 11 ++ .../Data/AnalysisStatistics.cs | 133 ++++++++++++++++++ .../Plugin.cs | 5 + .../ScheduledTasks/FingerprinterTask.cs | 31 +++- 6 files changed, 243 insertions(+), 3 deletions(-) create mode 100644 ConfusedPolarBear.Plugin.IntroSkipper.Tests/TestStatistics.cs create mode 100644 ConfusedPolarBear.Plugin.IntroSkipper/Data/AnalysisStatistics.cs diff --git a/ConfusedPolarBear.Plugin.IntroSkipper.Tests/TestStatistics.cs b/ConfusedPolarBear.Plugin.IntroSkipper.Tests/TestStatistics.cs new file mode 100644 index 0000000..66b2e34 --- /dev/null +++ b/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); + } +} diff --git a/ConfusedPolarBear.Plugin.IntroSkipper/Configuration/configPage.html b/ConfusedPolarBear.Plugin.IntroSkipper/Configuration/configPage.html index 3730c82..1666214 100644 --- a/ConfusedPolarBear.Plugin.IntroSkipper/Configuration/configPage.html +++ b/ConfusedPolarBear.Plugin.IntroSkipper/Configuration/configPage.html @@ -105,6 +105,12 @@ +
+ Analysis Statistics + + 

+
+
Fingerprint Visualizer @@ -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); diff --git a/ConfusedPolarBear.Plugin.IntroSkipper/Controllers/VisualizationController.cs b/ConfusedPolarBear.Plugin.IntroSkipper/Controllers/VisualizationController.cs index 0aa5bde..5dbb778 100644 --- a/ConfusedPolarBear.Plugin.IntroSkipper/Controllers/VisualizationController.cs +++ b/ConfusedPolarBear.Plugin.IntroSkipper/Controllers/VisualizationController.cs @@ -150,6 +150,17 @@ public class VisualizationController : ControllerBase return NoContent(); } + /// + /// Returns the statistics for the most recent analysis. + /// + /// Analysis statistics. + /// AnalysisStatistics. + [HttpGet("Statistics")] + public ActionResult GetAnalysisStatistics() + { + return Plugin.Instance!.AnalysisStatistics; + } + private string GetSeasonName(QueuedEpisode episode) { return "Season " + episode.SeasonNumber.ToString(CultureInfo.InvariantCulture); diff --git a/ConfusedPolarBear.Plugin.IntroSkipper/Data/AnalysisStatistics.cs b/ConfusedPolarBear.Plugin.IntroSkipper/Data/AnalysisStatistics.cs new file mode 100644 index 0000000..8ca0e27 --- /dev/null +++ b/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; + +/// +/// Detailed statistics about the last analysis operation performed. All times are represented as milliseconds. +/// +public class AnalysisStatistics +{ + /// + /// Gets the number of episodes that have been analyzed so far. + /// + public ThreadSafeInteger TotalAnalyzedEpisodes { get; } = new ThreadSafeInteger(); + + /// + /// Gets or sets the number of episodes that need to be analyzed. + /// + public int TotalQueuedEpisodes { get; set; } + + /// + /// Gets the number of times a quick scan successfully located a pair of introductions. + /// + public ThreadSafeInteger QuickScans { get; } = new ThreadSafeInteger(); + + /// + /// Gets the number of times a full scan successfully located a pair of introductions. + /// + public ThreadSafeInteger FullScans { get; } = new ThreadSafeInteger(); + + /// + /// Gets the total CPU time spent waiting for audio fingerprints to be generated. + /// + public ThreadSafeInteger FingerprintCPUTime { get; } = new ThreadSafeInteger(); + + /// + /// Gets the total CPU time spent analyzing fingerprints in the initial pass. + /// + public ThreadSafeInteger FirstPassCPUTime { get; } = new ThreadSafeInteger(); + + /// + /// Gets the total CPU time spent analyzing fingerprints in the second pass. + /// + public ThreadSafeInteger SecondPassCPUTime { get; } = new ThreadSafeInteger(); + + /// + /// Gets the total task runtime across all threads. + /// + public ThreadSafeInteger TotalCPUTime { get; } = new ThreadSafeInteger(); + + /// + /// Gets the total task runtime as measured by a clock. + /// + public ThreadSafeInteger TotalTaskTime { get; } = new ThreadSafeInteger(); +} + +/// +/// Convenience wrapper around a thread safe integer. +/// +[JsonConverter(typeof(ThreadSafeIntegerJsonConverter))] +public class ThreadSafeInteger +{ + private int value = 0; + + /// + /// Gets the current value stored by this integer. + /// + public int Value + { + get + { + return value; + } + } + + /// + /// Increment the value of this integer by 1. + /// + public void Increment() + { + Add(1); + } + + /// + /// Adds the total milliseconds elapsed since a start time. + /// + /// Start time. + public void AddDuration(DateTime start) + { + var elapsed = DateTime.Now.Subtract(start); + Add((int)elapsed.TotalMilliseconds); + } + + /// + /// Adds the provided amount to this integer. + /// + /// Amount to add. + public void Add(int amount) + { + Interlocked.Add(ref value, amount); + } +} + +/// +/// Serialize thread safe integers to a regular integer (instead of an object with a Value property). +/// +public class ThreadSafeIntegerJsonConverter : JsonConverter +{ + /// + /// Deserialization of TSIs is not supported and will always throw a NotSupportedException. + /// + /// Reader. + /// Type. + /// Options. + /// Never returns. + public override ThreadSafeInteger? Read(ref Utf8JsonReader reader, Type typeToConvert, JsonSerializerOptions options) + { + throw new NotSupportedException(); + } + + /// + /// Serialize the provided TSI. + /// + /// Writer. + /// TSI. + /// Options. + public override void Write(Utf8JsonWriter writer, ThreadSafeInteger value, JsonSerializerOptions options) + { + writer.WriteNumberValue(value.Value); + } +} diff --git a/ConfusedPolarBear.Plugin.IntroSkipper/Plugin.cs b/ConfusedPolarBear.Plugin.IntroSkipper/Plugin.cs index d69d790..1e2ad9d 100644 --- a/ConfusedPolarBear.Plugin.IntroSkipper/Plugin.cs +++ b/ConfusedPolarBear.Plugin.IntroSkipper/Plugin.cs @@ -74,6 +74,11 @@ public class Plugin : BasePlugin, IHasWebPages /// public int TotalQueued { get; set; } + /// + /// Gets or sets the statistics from the most recent analysis run. + /// + public AnalysisStatistics AnalysisStatistics { get; set; } = new AnalysisStatistics(); + /// /// Gets the directory to cache fingerprints in. /// diff --git a/ConfusedPolarBear.Plugin.IntroSkipper/ScheduledTasks/FingerprinterTask.cs b/ConfusedPolarBear.Plugin.IntroSkipper/ScheduledTasks/FingerprinterTask.cs index a162394..3598997 100644 --- a/ConfusedPolarBear.Plugin.IntroSkipper/ScheduledTasks/FingerprinterTask.cs +++ b/ConfusedPolarBear.Plugin.IntroSkipper/ScheduledTasks/FingerprinterTask.cs @@ -68,6 +68,11 @@ public class FingerprinterTask : IScheduledTask /// private Dictionary> _fingerprintCache; + /// + /// Statistics for the currently running analysis task. + /// + private AnalysisStatistics analysisStatistics = new AnalysisStatistics(); + /// /// Initializes a new instance of the class. /// @@ -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 /// Intros for the first and second episodes. 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 rhsPoints) { + var start = DateTime.Now; var lhsRanges = new List(); var rhsRanges = new List(); @@ -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)); }