From 3f82c90c48f2ec3ada36259aae7f2ab69d6cd77b Mon Sep 17 00:00:00 2001 From: Bond-009 Date: Wed, 14 Dec 2022 22:03:38 +0100 Subject: [PATCH] Improve DB perf for everyone not using debug logging (#8827) --- .../Data/SqliteItemRepository.cs | 230 +++++++++--------- 1 file changed, 115 insertions(+), 115 deletions(-) diff --git a/Emby.Server.Implementations/Data/SqliteItemRepository.cs b/Emby.Server.Implementations/Data/SqliteItemRepository.cs index 151476260..9bdc4e5c8 100644 --- a/Emby.Server.Implementations/Data/SqliteItemRepository.cs +++ b/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); - } - - BindSimilarParams(query, statement); - BindSearchParams(query, statement); - - // Running this again will bind the params - GetWhereClauses(query, statement); - - count = statement.ExecuteQuery().SelectScalarInt().First(); + statement.TryBind("@UserId", query.User.InternalId); } - } - LogQueryTime("GetCount", commandText, now); - return count; + BindSimilarParams(query, statement); + BindSearchParams(query, statement); + + // Running this again will bind the params + GetWhereClauses(query, statement); + + return statement.ExecuteQuery().SelectScalarInt().First(); + } } public List 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(); + 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); - } - - BindSimilarParams(query, statement); - BindSearchParams(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); - - foreach (var row in statement.ExecuteQuery()) - { - var item = GetItem(row, query, hasProgramAttributes, hasEpisodeAttributes, hasServiceName, hasStartDate, hasTrailerTypes, hasArtistFields, hasSeriesFields); - if (item is not null) - { - items.Add(item); - } - } + statement.TryBind("@UserId", query.User.InternalId); } - // Hack for right now since we currently don't support filtering out these duplicates within a query - if (query.EnableGroupByMetadataKey) + BindSimilarParams(query, statement); + BindSearchParams(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); + + foreach (var row in statement.ExecuteQuery()) { - var limit = query.Limit ?? int.MaxValue; - limit -= 4; - var newList = new List(); - - foreach (var item in items) + var item = GetItem(row, query, hasProgramAttributes, hasEpisodeAttributes, hasServiceName, hasStartDate, hasTrailerTypes, hasArtistFields, hasSeriesFields); + if (item is not null) { - AddItem(newList, item); - - if (newList.Count >= limit) - { - break; - } + items.Add(item); } - - items = newList; } } - LogQueryTime("GetItemList", commandText, now); + // 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(); + + foreach (var item in items) + { + AddItem(newList, item); + + if (newList.Count >= limit) + { + break; + } + } + + 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 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 { "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(); + 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(); + 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); + } + } + } } }