Improve DB perf for everyone not using debug logging (#8827)

Emby.Server.Implementations/Data/SqliteItemRepository.cs

@@ -5,9 +5,11 @@
 using System;
 using System.Buffers.Text;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Globalization;
 using System.IO;
 using System.Linq;
+using System.Runtime.CompilerServices;
 using System.Text;
 using System.Text.Json;
 using System.Threading;
@@ -2558,8 +2560,6 @@ namespace Emby.Server.Implementations.Data
 
             CheckDisposed();
 
-            var now = DateTime.UtcNow;
-
             // Hack for right now since we currently don't support filtering out these duplicates within a query
             if (query.Limit.HasValue && query.EnableGroupByMetadataKey)
             {
@@ -2581,28 +2581,24 @@ namespace Emby.Server.Implementations.Data
             }
 
             var commandText = commandTextBuilder.ToString();
-            int count;
+
+            using (new QueryTimeLogger(Logger, commandText))
             using (var connection = GetConnection(true))
+            using (var statement = PrepareStatement(connection, commandText))
             {
-                using (var statement = PrepareStatement(connection, commandText))
+                if (EnableJoinUserData(query))
                 {
-                    if (EnableJoinUserData(query))
-                    {
-                        statement.TryBind("@UserId", query.User.InternalId);
-                    }
+                    statement.TryBind("@UserId", query.User.InternalId);
+                }
 
-                    BindSimilarParams(query, statement);
-                    BindSearchParams(query, statement);
+                BindSimilarParams(query, statement);
+                BindSearchParams(query, statement);
 
-                    // Running this again will bind the params
-                    GetWhereClauses(query, statement);
+                // Running this again will bind the params
+                GetWhereClauses(query, statement);
 
-                    count = statement.ExecuteQuery().SelectScalarInt().First();
-                }
+                return statement.ExecuteQuery().SelectScalarInt().First();
             }
-
-            LogQueryTime("GetCount", commandText, now);
-            return count;
         }
 
         public List<BaseItem> GetItemList(InternalItemsQuery query)
@@ -2611,8 +2607,6 @@ namespace Emby.Server.Implementations.Data
 
             CheckDisposed();
 
-            var now = DateTime.UtcNow;
-
             // Hack for right now since we currently don't support filtering out these duplicates within a query
             if (query.Limit.HasValue && query.EnableGroupByMetadataKey)
             {
@@ -2656,61 +2650,58 @@ namespace Emby.Server.Implementations.Data
 
             var commandText = commandTextBuilder.ToString();
             var items = new List<BaseItem>();
+            using (new QueryTimeLogger(Logger, commandText))
             using (var connection = GetConnection(true))
+            using (var statement = PrepareStatement(connection, commandText))
             {
-                using (var statement = PrepareStatement(connection, commandText))
+                if (EnableJoinUserData(query))
                 {
-                    if (EnableJoinUserData(query))
-                    {
-                        statement.TryBind("@UserId", query.User.InternalId);
-                    }
+                    statement.TryBind("@UserId", query.User.InternalId);
+                }
 
-                    BindSimilarParams(query, statement);
-                    BindSearchParams(query, statement);
+                BindSimilarParams(query, statement);
+                BindSearchParams(query, statement);
 
-                    // Running this again will bind the params
-                    GetWhereClauses(query, statement);
+                // Running this again will bind the params
+                GetWhereClauses(query, statement);
 
-                    var hasEpisodeAttributes = HasEpisodeAttributes(query);
-                    var hasServiceName = HasServiceName(query);
-                    var hasProgramAttributes = HasProgramAttributes(query);
-                    var hasStartDate = HasStartDate(query);
-                    var hasTrailerTypes = HasTrailerTypes(query);
-                    var hasArtistFields = HasArtistFields(query);
-                    var hasSeriesFields = HasSeriesFields(query);
+                var hasEpisodeAttributes = HasEpisodeAttributes(query);
+                var hasServiceName = HasServiceName(query);
+                var hasProgramAttributes = HasProgramAttributes(query);
+                var hasStartDate = HasStartDate(query);
+                var hasTrailerTypes = HasTrailerTypes(query);
+                var hasArtistFields = HasArtistFields(query);
+                var hasSeriesFields = HasSeriesFields(query);
 
-                    foreach (var row in statement.ExecuteQuery())
+                foreach (var row in statement.ExecuteQuery())
+                {
+                    var item = GetItem(row, query, hasProgramAttributes, hasEpisodeAttributes, hasServiceName, hasStartDate, hasTrailerTypes, hasArtistFields, hasSeriesFields);
+                    if (item is not null)
                     {
-                        var item = GetItem(row, query, hasProgramAttributes, hasEpisodeAttributes, hasServiceName, hasStartDate, hasTrailerTypes, hasArtistFields, hasSeriesFields);
-                        if (item is not null)
-                        {
-                            items.Add(item);
-                        }
+                        items.Add(item);
                     }
                 }
+            }
 
-                // Hack for right now since we currently don't support filtering out these duplicates within a query
-                if (query.EnableGroupByMetadataKey)
+            // Hack for right now since we currently don't support filtering out these duplicates within a query
+            if (query.EnableGroupByMetadataKey)
+            {
+                var limit = query.Limit ?? int.MaxValue;
+                limit -= 4;
+                var newList = new List<BaseItem>();
+
+                foreach (var item in items)
                 {
-                    var limit = query.Limit ?? int.MaxValue;
-                    limit -= 4;
-                    var newList = new List<BaseItem>();
+                    AddItem(newList, item);
 
-                    foreach (var item in items)
+                    if (newList.Count >= limit)
                     {
-                        AddItem(newList, item);
-
-                        if (newList.Count >= limit)
-                        {
-                            break;
-                        }
+                        break;
                     }
-
-                    items = newList;
                 }
-            }
 
-            LogQueryTime("GetItemList", commandText, now);
+                items = newList;
+            }
 
             return items;
         }
@@ -2763,26 +2754,6 @@ namespace Emby.Server.Implementations.Data
             items.Add(newItem);
         }
 
-        private void LogQueryTime(string methodName, string commandText, DateTime startDate)
-        {
-            var elapsed = (DateTime.UtcNow - startDate).TotalMilliseconds;
-
-#if DEBUG
-            const int SlowThreshold = 100;
-#else
-            const int SlowThreshold = 10;
-#endif
-
-            if (elapsed >= SlowThreshold)
-            {
-                Logger.LogDebug(
-                    "{Method} query time (slow): {ElapsedMs}ms. Query: {Query}",
-                    methodName,
-                    elapsed,
-                    commandText);
-            }
-        }
-
         public QueryResult<BaseItem> GetItems(InternalItemsQuery query)
         {
             ArgumentNullException.ThrowIfNull(query);
@@ -2798,8 +2769,6 @@ namespace Emby.Server.Implementations.Data
                     returnList);
             }
 
-            var now = DateTime.UtcNow;
-
             // Hack for right now since we currently don't support filtering out these duplicates within a query
             if (query.Limit.HasValue && query.EnableGroupByMetadataKey)
             {
@@ -2900,6 +2869,7 @@ namespace Emby.Server.Implementations.Data
 
                         if (!isReturningZeroItems)
                         {
+                            using (new QueryTimeLogger(Logger, itemQuery, "GetItems.ItemQuery"))
                             using (var statement = itemQueryStatement)
                             {
                                 if (EnableJoinUserData(query))
@@ -2930,13 +2900,11 @@ namespace Emby.Server.Implementations.Data
                                     }
                                 }
                             }
-
-                            LogQueryTime("GetItems.ItemQuery", itemQuery, now);
                         }
 
-                        now = DateTime.UtcNow;
                         if (query.EnableTotalRecordCount)
                         {
+                            using (new QueryTimeLogger(Logger, totalRecordCountQuery, "GetItems.TotalRecordCount"))
                             using (var statement = totalRecordCountQueryStatement)
                             {
                                 if (EnableJoinUserData(query))
@@ -2952,8 +2920,6 @@ namespace Emby.Server.Implementations.Data
 
                                 result.TotalRecordCount = statement.ExecuteQuery().SelectScalarInt().First();
                             }
-
-                            LogQueryTime("GetItems.TotalRecordCount", totalRecordCountQuery, now);
                         }
                     },
                     ReadTransactionMode);
@@ -3171,8 +3137,6 @@ namespace Emby.Server.Implementations.Data
 
             CheckDisposed();
 
-            var now = DateTime.UtcNow;
-
             var columns = new List<string> { "guid" };
             SetFinalColumnsToSelect(query, columns);
             var commandTextBuilder = new StringBuilder("select ", 256)
@@ -3209,29 +3173,27 @@ namespace Emby.Server.Implementations.Data
 
             var commandText = commandTextBuilder.ToString();
             var list = new List<Guid>();
+            using (new QueryTimeLogger(Logger, commandText))
             using (var connection = GetConnection(true))
+            using (var statement = PrepareStatement(connection, commandText))
             {
-                using (var statement = PrepareStatement(connection, commandText))
+                if (EnableJoinUserData(query))
                 {
-                    if (EnableJoinUserData(query))
-                    {
-                        statement.TryBind("@UserId", query.User.InternalId);
-                    }
+                    statement.TryBind("@UserId", query.User.InternalId);
+                }
 
-                    BindSimilarParams(query, statement);
-                    BindSearchParams(query, statement);
+                BindSimilarParams(query, statement);
+                BindSearchParams(query, statement);
 
-                    // Running this again will bind the params
-                    GetWhereClauses(query, statement);
+                // Running this again will bind the params
+                GetWhereClauses(query, statement);
 
-                    foreach (var row in statement.ExecuteQuery())
-                    {
-                        list.Add(row[0].ReadGuidFromBlob());
-                    }
+                foreach (var row in statement.ExecuteQuery())
+                {
+                    list.Add(row[0].ReadGuidFromBlob());
                 }
             }
 
-            LogQueryTime("GetItemList", commandText, now);
             return list;
         }
 
@@ -5112,8 +5074,6 @@ AND Type = @InternalPersonType)");
         {
             CheckDisposed();
 
-            var now = DateTime.UtcNow;
-
             var stringBuilder = new StringBuilder("Select Value From ItemValues where Type", 128);
             if (itemValueTypes.Length == 1)
             {
@@ -5145,6 +5105,7 @@ AND Type = @InternalPersonType)");
             var commandText = stringBuilder.ToString();
 
             var list = new List<string>();
+            using (new QueryTimeLogger(Logger, commandText))
             using (var connection = GetConnection(true))
             using (var statement = PrepareStatement(connection, commandText))
             {
@@ -5157,7 +5118,6 @@ AND Type = @InternalPersonType)");
                 }
             }
 
-            LogQueryTime("GetItemValueNames", commandText, now);
             return list;
         }
 
@@ -5172,8 +5132,6 @@ AND Type = @InternalPersonType)");
 
             CheckDisposed();
 
-            var now = DateTime.UtcNow;
-
             var typeClause = itemValueTypes.Length == 1 ?
                 ("Type=" + itemValueTypes[0]) :
                 ("Type in (" + string.Join(',', itemValueTypes) + ")");
@@ -5347,6 +5305,7 @@ AND Type = @InternalPersonType)");
 
             var list = new List<(BaseItem, ItemCounts)>();
             var result = new QueryResult<(BaseItem, ItemCounts)>();
+            using (new QueryTimeLogger(Logger, commandText))
             using (var connection = GetConnection(true))
             {
                 connection.RunInTransaction(
@@ -5420,8 +5379,6 @@ AND Type = @InternalPersonType)");
                     ReadTransactionMode);
             }
 
-            LogQueryTime("GetItemValues", commandText, now);
-
             if (result.TotalRecordCount == 0)
             {
                 result.TotalRecordCount = list.Count;
@@ -6246,5 +6203,48 @@ AND Type = @InternalPersonType)");
 
             return item;
         }
+
+#nullable enable
+
+        private readonly struct QueryTimeLogger : IDisposable
+        {
+            private readonly ILogger _logger;
+            private readonly string _commandText;
+            private readonly string _methodName;
+            private readonly long _startTimestamp;
+
+            public QueryTimeLogger(ILogger logger, string commandText, [CallerMemberName] string methodName = "")
+            {
+                _logger = logger;
+                _commandText = commandText;
+                _methodName = methodName;
+                _startTimestamp = logger.IsEnabled(LogLevel.Debug) ? Stopwatch.GetTimestamp() : -1;
+            }
+
+            public void Dispose()
+            {
+                if (_startTimestamp == -1)
+                {
+                    return;
+                }
+
+                var elapsedMs = Stopwatch.GetElapsedTime(_startTimestamp).TotalMilliseconds;
+
+#if DEBUG
+                const int SlowThreshold = 100;
+#else
+                const int SlowThreshold = 10;
+#endif
+
+                if (elapsedMs >= SlowThreshold)
+                {
+                    _logger.LogDebug(
+                        "{Method} query time (slow): {ElapsedMs}ms. Query: {Query}",
+                        _methodName,
+                        elapsedMs,
+                        _commandText);
+                }
+            }
+        }
     }
 }