collect and print timings during jellyfin show library scans (#2748)

* collect and print timings during jellyfin show library scans

* update p99

ErsatzTV.Infrastructure/Data/Repositories/JellyfinTelevisionRepository.cs

@@ -85,6 +85,8 @@ public class JellyfinTelevisionRepository : IJellyfinTelevisionRepository
         JellyfinLibrary library,
         JellyfinShow item,
         CancellationToken cancellationToken)
+    {
+        using (ScanProfiler.Measure("DB Ins/Upd Show"))
         {
             await using TvContext dbContext = await _dbContextFactory.CreateDbContextAsync(cancellationToken);
             Option<JellyfinShow> maybeExisting = await dbContext.JellyfinShows
@@ -121,11 +123,14 @@ public class JellyfinTelevisionRepository : IJellyfinTelevisionRepository
 
             return await AddShow(dbContext, library, item, cancellationToken);
         }
+    }
 
     public async Task<Either<BaseError, MediaItemScanResult<JellyfinSeason>>> GetOrAdd(
         JellyfinLibrary library,
         JellyfinSeason item,
         CancellationToken cancellationToken)
+    {
+        using (ScanProfiler.Measure("DB Ins/Upd Season"))
         {
             await using TvContext dbContext = await _dbContextFactory.CreateDbContextAsync(cancellationToken);
             Option<JellyfinSeason> maybeExisting = await dbContext.JellyfinSeasons
@@ -151,12 +156,15 @@ public class JellyfinTelevisionRepository : IJellyfinTelevisionRepository
 
             return await AddSeason(dbContext, library, item, cancellationToken);
         }
+    }
 
     public async Task<Either<BaseError, MediaItemScanResult<JellyfinEpisode>>> GetOrAdd(
         JellyfinLibrary library,
         JellyfinEpisode item,
         bool deepScan,
         CancellationToken cancellationToken)
+    {
+        using (ScanProfiler.Measure("DB Ins/Upd Episode"))
         {
             await using TvContext dbContext = await _dbContextFactory.CreateDbContextAsync(cancellationToken);
             Option<JellyfinEpisode> maybeExisting = await dbContext.JellyfinEpisodes
@@ -204,6 +212,7 @@ public class JellyfinTelevisionRepository : IJellyfinTelevisionRepository
 
             return await AddEpisode(dbContext, library, item, cancellationToken);
         }
+    }
 
     public async Task<Unit> SetEtag(JellyfinShow show, string etag, CancellationToken cancellationToken)
     {

ErsatzTV.Infrastructure/Jellyfin/JellyfinApiClient.cs

@@ -81,6 +81,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         string apiKey,
         JellyfinLibrary library) =>
         GetPagedLibraryItems(
+            "JF Movies",
             address,
             library,
             library.MediaSourceId,
@@ -97,6 +98,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         string apiKey,
         JellyfinLibrary library) =>
         GetPagedLibraryItems(
+            "JF Shows",
             address,
             library,
             library.MediaSourceId,
@@ -114,6 +116,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         JellyfinLibrary library,
         string showId) =>
         GetPagedLibraryItems(
+            "JF Seasons",
             address,
             library,
             library.MediaSourceId,
@@ -131,6 +134,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         JellyfinLibrary library,
         string seasonId) =>
         GetPagedLibraryItems(
+            "JF Episodes*",
             address,
             library,
             library.MediaSourceId,
@@ -148,6 +152,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         JellyfinLibrary library,
         string seasonId) =>
         GetPagedLibraryItems(
+            "JF Episodes",
             address,
             library,
             library.MediaSourceId,
@@ -169,6 +174,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         if (_memoryCache.TryGetValue("jellyfin_collections_library_item_id", out string itemId))
         {
             return GetPagedLibraryItems(
+                "JF Collections",
                 address,
                 None,
                 mediaSourceId,
@@ -190,6 +196,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         int mediaSourceId,
         string collectionId) =>
         GetPagedLibraryItems(
+            "JF Collection Items",
             address,
             None,
             mediaSourceId,
@@ -208,12 +215,15 @@ public class JellyfinApiClient : IJellyfinApiClient
         string itemId)
     {
         try
+        {
+            using (ScanProfiler.Measure("JF Playback Info"))
             {
                 IJellyfinApi service = ServiceForAddress(address);
                 JellyfinPlaybackInfoResponse playbackInfo = await service.GetPlaybackInfo(apiKey, itemId);
                 Option<MediaVersion> maybeVersion = ProjectToMediaVersion(playbackInfo);
                 return maybeVersion.ToEither(() => BaseError.New("Unable to locate Jellyfin statistics"));
             }
+        }
         catch (Exception ex)
         {
             _logger.LogError(ex, "Error getting jellyfin playback info");
@@ -228,6 +238,8 @@ public class JellyfinApiClient : IJellyfinApiClient
         string showId)
     {
         try
+        {
+            using (ScanProfiler.Measure("JF Single Show"))
             {
                 IJellyfinApi service = ServiceForAddress(address);
                 JellyfinLibraryItemsResponse itemsResponse = await service.GetShowLibraryItems(
@@ -245,6 +257,7 @@ public class JellyfinApiClient : IJellyfinApiClient
 
                 return BaseError.New($"Unable to locate show with id {showId}");
             }
+        }
         catch (Exception ex)
         {
             _logger.LogError(ex, "Error searching Jellyfin shows by id");
@@ -309,6 +322,8 @@ public class JellyfinApiClient : IJellyfinApiClient
         string episodeId)
     {
         try
+        {
+            using (ScanProfiler.Measure("JF Single Episode"))
             {
                 IJellyfinApi service = ServiceForAddress(address);
                 JellyfinLibraryItemsResponse itemsResponse = await service.GetEpisodeLibraryItems(
@@ -326,6 +341,7 @@ public class JellyfinApiClient : IJellyfinApiClient
 
                 return BaseError.New($"Unable to locate episode with id {episodeId}");
             }
+        }
         catch (Exception ex)
         {
             _logger.LogError(ex, "Error searching Jellyfin episodes by id");
@@ -334,6 +350,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     }
 
     private async IAsyncEnumerable<Tuple<TItem, int>> GetPagedLibraryItems<TItem>(
+        string pageDescription,
         string address,
         Option<JellyfinLibrary> maybeLibrary,
         int mediaSourceId,
@@ -348,11 +365,16 @@ public class JellyfinApiClient : IJellyfinApiClient
         {
             int skip = i * SystemEnvironment.JellyfinPageSize;
 
-            JellyfinLibraryItemsResponse result = await getItems(
+            JellyfinLibraryItemsResponse result;
+
+            using (ScanProfiler.Measure(pageDescription))
+            {
+                result = await getItems(
                     service,
                     parentId,
                     skip,
                     SystemEnvironment.JellyfinPageSize);
+            }
 
             // update page count
             pages = Math.Min(pages, (result.TotalRecordCount - 1) / SystemEnvironment.JellyfinPageSize + 1);

ErsatzTV.Infrastructure/ScanProfiler.cs

@@ -0,0 +1,61 @@
+using System.Collections.Concurrent;
+using System.Diagnostics;
+
+namespace ErsatzTV.Infrastructure;
+
+public static class ScanProfiler
+{
+    private static readonly ConcurrentDictionary<string, ConcurrentBag<long>> Measurements = new();
+
+    public static IDisposable Measure(string operationName)
+    {
+        return new TimerToken(operationName);
+    }
+
+    public static void Reset() => Measurements.Clear();
+
+    public static void LogStatistics(Action<string> logAction)
+    {
+        if (Measurements.IsEmpty)
+        {
+            return;
+        }
+
+        var sb = new System.Text.StringBuilder();
+        sb.AppendLine("Scan Performance Summary:");
+        sb.AppendLine(FormattableString.Invariant($"{"Operation",-25} | {"Count",-6} | {"Avg (ms)",-8} | {"Min",-6} | {"Max",-6} | {"P99",-6} | {"Total (s)",-8}"));
+        sb.AppendLine(new string('-', 85));
+
+        foreach (string key in Measurements.Keys.OrderBy(k => k))
+        {
+            var times = Measurements[key].ToList();
+            if (times.Count == 0) continue;
+
+            times.Sort();
+            double avg = times.Average();
+            long min = times.Min();
+            long max = times.Max();
+            int n = times.Count;
+            int idx = (int)Math.Ceiling(0.99 * n) - 1;
+            idx = Math.Clamp(idx, 0, n - 1);
+            long p99 = times[idx];
+            double totalSec = times.Sum() / 1000.0;
+
+            sb.AppendLine(FormattableString.Invariant($"{key,-25} | {times.Count,-6} | {avg,-8:F1} | {min,-6} | {max,-6} | {p99,-6} | {totalSec,-8:F2}"));
+        }
+
+        logAction(sb.ToString());
+    }
+
+    private readonly struct TimerToken(string name) : IDisposable
+    {
+        private readonly long _startTime = Stopwatch.GetTimestamp();
+
+        public void Dispose()
+        {
+            long elapsedMs = (long)Stopwatch.GetElapsedTime(_startTime).TotalMilliseconds;
+            ConcurrentBag<long> bag = Measurements.GetOrAdd(name, _ => []);
+            bag.Add(elapsedMs);
+        }
+    }
+}

ErsatzTV.Scanner/Core/Metadata/MediaServerTelevisionLibraryScanner.cs

@@ -6,6 +6,7 @@ using ErsatzTV.Core.Errors;
 using ErsatzTV.Core.Extensions;
 using ErsatzTV.Core.Interfaces.Repositories;
 using ErsatzTV.Core.Metadata;
+using ErsatzTV.Infrastructure;
 using ErsatzTV.Scanner.Core.Interfaces;
 using ErsatzTV.Scanner.Core.Interfaces.Metadata;
 using Microsoft.Extensions.Logging;
@@ -94,6 +95,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         List<TEtag> existingShows = await televisionRepository.GetExistingShows(library, cancellationToken);
 
         await foreach ((TShow incoming, int totalShowCount) in showEntries.WithCancellation(cancellationToken))
+        {
+            using (ScanProfiler.Measure("Scan Show"))
             {
                 if (cancellationToken.IsCancellationRequested)
                 {
@@ -145,7 +148,10 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
 
                     await televisionRepository.SetEtag(result.Item, MediaServerEtag(incoming), cancellationToken);
 
-                Option<int> flagResult = await televisionRepository.FlagNormal(library, result.Item, cancellationToken);
+                    Option<int> flagResult = await televisionRepository.FlagNormal(
+                        library,
+                        result.Item,
+                        cancellationToken);
                     if (flagResult.IsSome)
                     {
                         result.IsUpdated = true;
@@ -161,6 +167,9 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                 }
             }
 
+            ScanProfiler.LogStatistics(s => _logger.LogInformation("{Profile}", s));
+        }
+
         if (cleanupFileNotFoundItems)
         {
             // trash shows that are no longer present on the media server
@@ -284,6 +293,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         List<TEtag> existingSeasons = await televisionRepository.GetExistingSeasons(library, show, cancellationToken);
 
         await foreach ((TSeason incoming, int _) in seasonEntries.WithCancellation(cancellationToken))
+        {
+            using (ScanProfiler.Measure("Scan Season"))
             {
                 incoming.ShowId = show.Id;
 
@@ -333,7 +344,10 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
 
                     await televisionRepository.SetEtag(result.Item, MediaServerEtag(incoming), cancellationToken);
 
-                Option<int> flagResult = await televisionRepository.FlagNormal(library, result.Item, cancellationToken);
+                    Option<int> flagResult = await televisionRepository.FlagNormal(
+                        library,
+                        result.Item,
+                        cancellationToken);
                     if (flagResult.IsSome)
                     {
                         result.IsUpdated = true;
@@ -350,6 +364,7 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                     }
                 }
             }
+        }
 
         // trash seasons that are no longer present on the media server
         var fileNotFoundItemIds = existingSeasons.Map(s => s.MediaServerItemId).Except(incomingItemIds).ToList();
@@ -378,6 +393,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         List<TEtag> existingEpisodes = await televisionRepository.GetExistingEpisodes(library, season, cancellationToken);
 
         await foreach ((TEpisode incoming, int _) in episodeEntries.WithCancellation(cancellationToken))
+        {
+            using (ScanProfiler.Measure("Scan Episode"))
             {
                 if (cancellationToken.IsCancellationRequested)
                 {
@@ -472,7 +489,10 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
 
                     if (_fileSystem.File.Exists(result.LocalPath))
                     {
-                    Option<int> flagResult = await televisionRepository.FlagNormal(library, result.Item, cancellationToken);
+                        Option<int> flagResult = await televisionRepository.FlagNormal(
+                            library,
+                            result.Item,
+                            cancellationToken);
                         if (flagResult.IsSome)
                         {
                             result.IsUpdated = true;
@@ -480,7 +500,10 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                     }
                     else if (ServerSupportsRemoteStreaming)
                     {
-                    Option<int> flagResult = await televisionRepository.FlagRemoteOnly(library, result.Item, cancellationToken);
+                        Option<int> flagResult = await televisionRepository.FlagRemoteOnly(
+                            library,
+                            result.Item,
+                            cancellationToken);
                         if (flagResult.IsSome)
                         {
                             result.IsUpdated = true;
@@ -488,7 +511,10 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                     }
                     else
                     {
-                    Option<int> flagResult = await televisionRepository.FlagUnavailable(library, result.Item, cancellationToken);
+                        Option<int> flagResult = await televisionRepository.FlagUnavailable(
+                            library,
+                            result.Item,
+                            cancellationToken);
                         if (flagResult.IsSome)
                         {
                             result.IsUpdated = true;
@@ -505,6 +531,7 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                     }
                 }
             }
+        }
 
         // trash episodes that are no longer present on the media server
         var fileNotFoundItemIds = existingEpisodes.Map(m => m.MediaServerItemId).Except(incomingItemIds).ToList();
@@ -610,6 +637,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         MediaItemScanResult<TShow> result,
         TShow incoming,
         bool deepScan)
+    {
+        using (ScanProfiler.Measure("Update Show Metadata"))
         {
             foreach (ShowMetadata fullMetadata in await GetFullMetadata(
                          connectionParameters,
@@ -622,6 +651,7 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                 // will have to merge JF, Emby, Plex logic
                 return await UpdateMetadata(result, fullMetadata);
             }
+        }
 
         return result;
     }
@@ -632,6 +662,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         MediaItemScanResult<TSeason> result,
         TSeason incoming,
         bool deepScan)
+    {
+        using (ScanProfiler.Measure("Update Season Metadata"))
         {
             foreach (SeasonMetadata fullMetadata in await GetFullMetadata(
                          connectionParameters,
@@ -644,6 +676,7 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                 // will have to merge JF, Emby, Plex logic
                 return await UpdateMetadata(result, fullMetadata);
             }
+        }
 
         return result;
     }
@@ -713,6 +746,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         bool deepScan,
         Option<EpisodeMetadata> maybeFullMetadata,
         CancellationToken cancellationToken)
+    {
+        using (ScanProfiler.Measure("Update Episode Metadata"))
         {
             if (maybeFullMetadata.IsNone)
             {
@@ -728,6 +763,7 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
 
             return result;
         }
+    }
 
     private async Task<Either<BaseError, MediaItemScanResult<TEpisode>>> UpdateStatistics(
         TConnectionParameters connectionParameters,
@@ -736,6 +772,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         TEpisode incoming,
         bool deepScan,
         Option<MediaVersion> maybeMediaVersion)
+    {
+        using (ScanProfiler.Measure("Update Episode Stats"))
         {
             TEpisode existing = result.Item;
 
@@ -789,12 +827,15 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
 
             return result;
         }
+    }
 
     private async Task<Either<BaseError, MediaItemScanResult<TEpisode>>> UpdateSubtitles(
         MediaItemScanResult<TEpisode> existing,
         CancellationToken cancellationToken)
     {
         try
+        {
+            using (ScanProfiler.Measure("Update Episode Subtitles"))
             {
                 MediaVersion version = existing.Item.GetHeadVersion();
                 Option<EpisodeMetadata> maybeMetadata = existing.Item.EpisodeMetadata.HeadOrNone();
@@ -813,6 +854,7 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
 
                 return BaseError.New("Failed to update media server subtitles");
             }
+        }
         catch (Exception ex)
         {
             return BaseError.New(ex.ToString());
@@ -824,6 +866,8 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
         CancellationToken cancellationToken)
     {
         try
+        {
+            using (ScanProfiler.Measure("Update Episode Chapters"))
             {
                 if (string.IsNullOrEmpty(existing.LocalPath))
                 {
@@ -831,13 +875,17 @@ public abstract class MediaServerTelevisionLibraryScanner<TConnectionParameters,
                     return existing;
                 }
 
-            if (await _localChaptersProvider.UpdateChapters(existing.Item, Some(existing.LocalPath), cancellationToken))
+                if (await _localChaptersProvider.UpdateChapters(
+                        existing.Item,
+                        Some(existing.LocalPath),
+                        cancellationToken))
                 {
                     existing.IsUpdated = true;
                 }
 
                 return existing;
             }
+        }
         catch (Exception ex)
         {
             return BaseError.New(ex.ToString());