add some performance troubleshooting env vars (#2745)

* add slow query logging

* add slow api logging for jellyfin

* add configurable jellyfin page size

* feedback

CHANGELOG.md

@@ -34,6 +34,12 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
   - This button will extract up to 30 seconds of the media item and zip it
 - Add `Target Loudness` (LUFS/LKFS) to ffmpeg profile when loudness normalization is enabled
   - Default value is `-16`; some sources normalize to a quieter value, e.g. `-24`
+- Add environment variables to help troubleshoot performance
+  - `ETV_SLOW_DB_MS` - milliseconds threshold for logging slow database queries (at DEBUG level)
+    - e.g. if this is set to `1000`, queries taking longer than 1 second will be logged
+  - `ETV_SLOW_API_MS` - milliseconds threshold for logging slow API calls (at DEBUG level)
+    - This is currently limited to *Jellyfin*
+  - `ETV_JF_PAGE_SIZE` - page size for library scan API calls to Jellyfin; default value is 10
 
 ### Fixed
 - Fix startup on systems unsupported by NvEncSharp

ErsatzTV.Core/SystemEnvironment.cs

@@ -36,6 +36,26 @@ public class SystemEnvironment
         }
 
         MaximumUploadMb = maximumUploadMb;
+
+        string slowDbMsVariable = Environment.GetEnvironmentVariable("ETV_SLOW_DB_MS");
+        if (int.TryParse(slowDbMsVariable, out int slowDbMs) && slowDbMs > 0)
+        {
+            SlowDbMs = slowDbMs;
+        }
+
+        string slowApiMsVariable = Environment.GetEnvironmentVariable("ETV_SLOW_API_MS");
+        if (int.TryParse(slowApiMsVariable, out int slowApiMs) && slowApiMs > 0)
+        {
+            SlowApiMs = slowApiMs;
+        }
+
+        string jellyfinPageSizeVariable = Environment.GetEnvironmentVariable("ETV_JF_PAGE_SIZE");
+        if (!int.TryParse(jellyfinPageSizeVariable, out int jellyfinPageSize) || jellyfinPageSize <= 0)
+        {
+            jellyfinPageSize = 10;
+        }
+
+        JellyfinPageSize = jellyfinPageSize;
     }
 
     public static string BaseUrl { get; }
@@ -45,4 +65,7 @@ public class SystemEnvironment
     public static int StreamingPort { get; }
     public static bool AllowSharedPlexServers { get; }
     public static int MaximumUploadMb { get; }
+    public static int? SlowDbMs { get; }
+    public static int? SlowApiMs { get; }
+    public static int JellyfinPageSize { get; }
 }

ErsatzTV.Infrastructure/Jellyfin/JellyfinApiClient.cs

@@ -15,6 +15,7 @@ namespace ErsatzTV.Infrastructure.Jellyfin;
 public class JellyfinApiClient : IJellyfinApiClient
 {
     private readonly IFallbackMetadataProvider _fallbackMetadataProvider;
+    private readonly IHttpClientFactory _httpClientFactory;
     private readonly IJellyfinPathReplacementService _jellyfinPathReplacementService;
     private readonly ILogger<JellyfinApiClient> _logger;
     private readonly IMemoryCache _memoryCache;
@@ -23,11 +24,13 @@ public class JellyfinApiClient : IJellyfinApiClient
         IMemoryCache memoryCache,
         IJellyfinPathReplacementService jellyfinPathReplacementService,
         IFallbackMetadataProvider fallbackMetadataProvider,
+        IHttpClientFactory httpClientFactory,
         ILogger<JellyfinApiClient> logger)
     {
         _memoryCache = memoryCache;
         _jellyfinPathReplacementService = jellyfinPathReplacementService;
         _fallbackMetadataProvider = fallbackMetadataProvider;
+        _httpClientFactory = httpClientFactory;
         _logger = logger;
     }
 
@@ -37,7 +40,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             var cts = new CancellationTokenSource();
             cts.CancelAfter(TimeSpan.FromSeconds(5));
             return await service.GetSystemInformation(apiKey, cts.Token)
@@ -59,7 +62,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             List<JellyfinLibraryResponse> libraries = await service.GetLibraries(apiKey);
             return libraries
                 .Map(Project)
@@ -189,7 +192,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            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"));
@@ -209,7 +212,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             JellyfinLibraryItemsResponse itemsResponse = await service.GetShowLibraryItems(
                 apiKey,
                 parentId: library.ItemId,
@@ -240,7 +243,7 @@ public class JellyfinApiClient : IJellyfinApiClient
     {
         try
         {
-            IJellyfinApi service = RestService.For<IJellyfinApi>(address);
+            IJellyfinApi service = ServiceForAddress(address);
             JellyfinSearchHintsResponse searchResponse = await service.SearchHints(
                 apiKey,
                 showTitle,
@@ -281,7 +284,7 @@ public class JellyfinApiClient : IJellyfinApiClient
         }
     }
 
-    private static async IAsyncEnumerable<Tuple<TItem, int>> GetPagedLibraryItems<TItem>(
+    private async IAsyncEnumerable<Tuple<TItem, int>> GetPagedLibraryItems<TItem>(
         string address,
         Option<JellyfinLibrary> maybeLibrary,
         int mediaSourceId,
@@ -289,19 +292,21 @@ public class JellyfinApiClient : IJellyfinApiClient
         Func<IJellyfinApi, string, int, int, Task<JellyfinLibraryItemsResponse>> getItems,
         Func<Option<JellyfinLibrary>, JellyfinLibraryItemResponse, Option<TItem>> mapper)
     {
-        IJellyfinApi service = RestService.For<IJellyfinApi>(address);
-
-        const int PAGE_SIZE = 10;
+        IJellyfinApi service = ServiceForAddress(address);
 
         int pages = int.MaxValue;
         for (var i = 0; i < pages; i++)
         {
-            int skip = i * PAGE_SIZE;
+            int skip = i * SystemEnvironment.JellyfinPageSize;
 
-            JellyfinLibraryItemsResponse result = await getItems(service, parentId, skip, PAGE_SIZE);
+            JellyfinLibraryItemsResponse result = await getItems(
+                service,
+                parentId,
+                skip,
+                SystemEnvironment.JellyfinPageSize);
 
             // update page count
-            pages = Math.Min(pages, (result.TotalRecordCount - 1) / PAGE_SIZE + 1);
+            pages = Math.Min(pages, (result.TotalRecordCount - 1) / SystemEnvironment.JellyfinPageSize + 1);
 
             foreach (TItem item in result.Items.Map(item => mapper(maybeLibrary, item)).Somes())
             {
@@ -1043,4 +1048,11 @@ public class JellyfinApiClient : IJellyfinApiClient
             return version;
         });
     }
+
+    private IJellyfinApi ServiceForAddress(string address)
+    {
+        var client = _httpClientFactory.CreateClient("RefitCustomClient");
+        client.BaseAddress = new Uri(address);
+        return RestService.For<IJellyfinApi>(client);
+    }
 }

ErsatzTV/SlowApiHandler.cs

@@ -0,0 +1,38 @@
+using ErsatzTV.Core;
+
+namespace ErsatzTV;
+
+using System.Diagnostics;
+
+public class SlowApiHandler(ILogger<SlowApiHandler> logger) : DelegatingHandler
+{
+    protected override async Task<HttpResponseMessage> SendAsync(
+        HttpRequestMessage request,
+        CancellationToken cancellationToken)
+    {
+        if (SystemEnvironment.SlowApiMs > 0)
+        {
+            var stopwatch = Stopwatch.StartNew();
+
+            var response = await base.SendAsync(request, cancellationToken);
+
+            stopwatch.Stop();
+
+            if (stopwatch.ElapsedMilliseconds > SystemEnvironment.SlowApiMs.Value)
+            {
+                string uri = request.RequestUri?.ToString() ?? "Unknown URI";
+                string method = request.Method.Method;
+
+                logger.LogDebug(
+                    "[SLOW API] {Method} {Uri} took {Milliseconds}ms",
+                    method,
+                    uri,
+                    stopwatch.ElapsedMilliseconds);
+            }
+
+            return response;
+        }
+
+        return await base.SendAsync(request, cancellationToken);
+    }
+}

ErsatzTV/SlowQueryInterceptor.cs

@@ -0,0 +1,24 @@
+using System.Data.Common;
+using Microsoft.EntityFrameworkCore.Diagnostics;
+
+namespace ErsatzTV;
+
+public class SlowQueryInterceptor(int threshold) : DbCommandInterceptor
+{
+    public override ValueTask<DbDataReader> ReaderExecutedAsync(
+        DbCommand command,
+        CommandExecutedEventData eventData,
+        DbDataReader result,
+        CancellationToken cancellationToken = default)
+    {
+        if (eventData.Duration.TotalMilliseconds > threshold)
+        {
+            Serilog.Log.Logger.Debug(
+                "[SLOW QUERY] ({Milliseconds}ms): {Command}",
+                eventData.Duration.TotalMilliseconds,
+                command.CommandText);
+        }
+
+        return base.ReaderExecutedAsync(command, eventData, result, cancellationToken);
+    }
+}

ErsatzTV/Startup.cs

@@ -408,6 +408,12 @@ public class Startup
         var sqliteConnectionString = $"Data Source={FileSystemLayout.DatabasePath};foreign keys=true;";
         string mySqlConnectionString = Configuration.GetValue<string>("MySql:ConnectionString");
 
+        SlowQueryInterceptor interceptor = null;
+        if (SystemEnvironment.SlowDbMs.HasValue)
+        {
+            interceptor = new SlowQueryInterceptor(SystemEnvironment.SlowDbMs.Value);
+        }
+
         services.AddDbContext<TvContext>(
             options =>
             {
@@ -438,6 +444,11 @@ public class Startup
                         }
                     );
                 }
+
+                if (interceptor != null)
+                {
+                    options.AddInterceptors(interceptor);
+                }
             },
             ServiceLifetime.Scoped,
             ServiceLifetime.Singleton);
@@ -467,6 +478,11 @@ public class Startup
                     }
                 );
             }
+
+            if (interceptor != null)
+            {
+                options.AddInterceptors(interceptor);
+            }
         });
 
         if (databaseProvider == Provider.Sqlite.Name)
@@ -509,6 +525,8 @@ public class Startup
                 c.DefaultRequestHeaders.Add("User-Agent", $"ErsatzTV/{etvVersion}");
             });
 
+        services.AddHttpClient("RefitCustomClient").AddHttpMessageHandler<SlowApiHandler>();
+
         services.Configure<TraktConfiguration>(Configuration.GetSection("Trakt"));
 
         services.AddResponseCompression(options => { options.EnableForHttps = true; });
@@ -851,6 +869,8 @@ public class Startup
 
         // services.AddTransient(typeof(IRequestHandler<,>), typeof(GetRecentLogEntriesHandler<>));
 
+        services.AddTransient<SlowApiHandler>();
+
         // run-once/blocking startup services
         services.AddHostedService<EndpointValidatorService>();
         services.AddHostedService<DatabaseMigratorService>();