yv01p/Umbraco-CMS
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Improve logging performance by checking Trace/Debug log level is enabled (#12793)

Browse Source
This commit is contained in:
Chad
2023-06-07 21:47:05 +12:00
committed by GitHub
parent 9bafdbd992
commit e784cfa960
69 changed files with 648 additions and 224 deletions
Download Patch File Download Diff File Expand all files Collapse all files

6
src/Umbraco.Web.Common/Controllers/RenderController.cs
View File

@@ -55,12 +55,14 @@ public class RenderController : UmbracoPageController, IRenderController
public override async Task OnActionExecutionAsync(ActionExecutingContext context, ActionExecutionDelegate next)
{
IPublishedRequest pcr = UmbracoRouteValues.PublishedRequest;
_logger.LogDebug(
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug(
"Response status: Content={Content}, StatusCode={ResponseStatusCode}, Culture={Culture}",
pcr.PublishedContent?.Id ?? -1,
pcr.ResponseStatusCode,
pcr.Culture);
}
UmbracoRouteResult routeStatus = pcr.GetRouteResult();
switch (routeStatus)

27
src/Umbraco.Web.Common/Macros/MacroRenderer.cs
View File

@@ -249,9 +249,10 @@ public class MacroRenderer : IMacroRenderer
{
return null;
}
_logger.LogDebug("Macro content loaded from cache '{MacroCacheId}'", model.CacheIdentifier);
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Macro content loaded from cache '{MacroCacheId}'", model.CacheIdentifier);
}
// ensure that the source has not changed
// note: does not handle dependencies, and never has
FileInfo? macroSource = GetMacroFile(model); // null if macro is not file-based
@@ -259,13 +260,19 @@ public class MacroRenderer : IMacroRenderer
{
if (macroSource.Exists == false)
{
_logger.LogDebug("Macro source does not exist anymore, ignore cache.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Macro source does not exist anymore, ignore cache.");
}
return null;
}
if (macroContent.Date < macroSource.LastWriteTime)
{
_logger.LogDebug("Macro source has changed, ignore cache.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Macro source has changed, ignore cache.");
}
return null;
}
}
@@ -304,8 +311,10 @@ public class MacroRenderer : IMacroRenderer
CacheKeys.MacroContentCacheKey + model.CacheIdentifier,
() => macroContent,
new TimeSpan(0, 0, model.CacheDuration));
_logger.LogDebug("Macro content saved to cache '{MacroCacheId}'", model.CacheIdentifier);
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Macro content saved to cache '{MacroCacheId}'", model.CacheIdentifier);
}
}
// gets the macro source file name
@@ -372,7 +381,7 @@ public class MacroRenderer : IMacroRenderer
}
var macroInfo = $"Render Macro: {macro.Name}, cache: {macro.CacheDuration}";
using (_profilingLogger.DebugDuration<MacroRenderer>(macroInfo, "Rendered Macro."))
using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration<MacroRenderer>(macroInfo, "Rendered Macro."))
{
// parse macro parameters ie replace the special [#key], [$key], etc. syntaxes
foreach (MacroPropertyModel prop in macro.Properties)
@@ -424,7 +433,7 @@ public class MacroRenderer : IMacroRenderer
/// </summary>
private Attempt<MacroContent?> ExecuteMacroWithErrorWrapper(MacroModel macro, string msgIn, string msgOut, Func<MacroContent> getMacroContent, Func<string> msgErr)
{
using (_profilingLogger.DebugDuration<MacroRenderer>(msgIn, msgOut))
using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration<MacroRenderer>(msgIn, msgOut))
{
return ExecuteProfileMacroWithErrorWrapper(macro, msgIn, getMacroContent, msgErr);
}

28
src/Umbraco.Web.Common/Middleware/UmbracoRequestMiddleware.cs
View File

@@ -114,9 +114,12 @@ public class UmbracoRequestMiddleware : IMiddleware
try
{
// Verbose log start of every request
LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache);
_logger.LogTrace("Begin request [{HttpRequestId}]: {RequestUrl}", httpRequestId, pathAndQuery);
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Trace))
{
// Verbose log start of every request
LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache);
_logger.LogTrace("Begin request [{HttpRequestId}]: {RequestUrl}", httpRequestId, pathAndQuery);
}
try
{
@@ -144,14 +147,17 @@ public class UmbracoRequestMiddleware : IMiddleware
}
finally
{
// Verbose log end of every request (in v8 we didn't log the end request of ALL requests, only the front-end which was
// strange since we always logged the beginning, so now we just log start/end of all requests)
LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache);
_logger.LogTrace(
"End Request [{HttpRequestId}]: {RequestUrl} ({RequestDuration}ms)",
httpRequestId,
pathAndQuery,
DateTime.Now.Subtract(umbracoContextReference.UmbracoContext.ObjectCreated).TotalMilliseconds);
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Trace))
{
// Verbose log end of every request (in v8 we didn't log the end request of ALL requests, only the front-end which was
// strange since we always logged the beginning, so now we just log start/end of all requests)
LogHttpRequest.TryGetCurrentHttpRequestId(out Guid? httpRequestId, _requestCache);
_logger.LogTrace(
"End Request [{HttpRequestId}]: {RequestUrl} ({RequestDuration}ms)",
httpRequestId,
pathAndQuery,
DateTime.Now.Subtract(umbracoContextReference.UmbracoContext.ObjectCreated).TotalMilliseconds);
}
try
{

77
src/Umbraco.Web.Common/ModelsBuilder/InMemoryAuto/InMemoryModelFactory.cs
View File

@@ -215,7 +215,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
// tells the factory that it should build a new generation of models
private void ResetModels()
{
_logger.LogDebug("Resetting models.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Resetting models.");
}
try
{
@@ -257,7 +260,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
{
if (_debugLevel > 0)
{
_logger.LogDebug("Ensuring models.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Ensuring models.");
}
}
// don't use an upgradeable lock here because only 1 thread at a time could enter it
@@ -291,7 +297,7 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
// we don't have models,
// either they haven't been loaded from the cache yet
// or they have been reseted and are pending a rebuild
using (_profilingLogger.DebugDuration<InMemoryModelFactory>("Get models.", "Got models."))
using (!_profilingLogger.IsEnabled(Core.Logging.LogLevel.Debug) ? null : _profilingLogger.DebugDuration<InMemoryModelFactory>("Get models.", "Got models."))
{
try
{
@@ -396,13 +402,19 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
// currentHash hashes both the types & the user's partials
if (!forceRebuild)
{
_logger.LogDebug("Looking for cached models.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Looking for cached models.");
}
if (File.Exists(modelsHashFile) && File.Exists(projFile))
{
var cachedHash = File.ReadAllText(modelsHashFile);
if (currentHash != cachedHash)
{
_logger.LogDebug("Found obsolete cached models.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Found obsolete cached models.");
}
forceRebuild = true;
}
@@ -426,8 +438,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
if (File.Exists(dllPathFile))
{
var dllPath = File.ReadAllText(dllPathFile);
_logger.LogDebug($"Cached models dll at {dllPath}.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Cached models dll at {dllPath}.",dllPath);
}
if (File.Exists(dllPath) && !File.Exists(dllPath + ".delete"))
{
@@ -441,24 +455,37 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
// ver 1, but we remember we want to skip that one - so we never end up
// with the "same but different" version of the assembly in memory
_skipver = assembly.GetName().Version?.Revision;
_logger.LogDebug("Loading cached models (dll).");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Loading cached models (dll).");
}
return assembly;
}
_logger.LogDebug("Cached models dll cannot be loaded (invalid assembly).");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Cached models dll cannot be loaded (invalid assembly).");
}
}
else if (!File.Exists(dllPath))
{
_logger.LogDebug("Cached models dll does not exist.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Cached models dll does not exist.");
}
}
else if (File.Exists(dllPath + ".delete"))
{
_logger.LogDebug("Cached models dll is marked for deletion.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Cached models dll is marked for deletion.");
}
}
else
{
_logger.LogDebug("Cached models dll cannot be loaded (why?).");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Cached models dll cannot be loaded (why?).");
}
}
}
@@ -487,13 +514,18 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
ClearOnFailingToCompile(dllPathFile, modelsHashFile, projFile);
throw;
}
_logger.LogDebug("Loading cached models (source).");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Loading cached models (source).");
}
return assembly;
}
// need to rebuild
_logger.LogDebug("Rebuilding models.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Rebuilding models.");
}
// generate code, save
var code = GenerateModelsCode(typeModels);
@@ -531,8 +563,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
ClearOnFailingToCompile(dllPathFile, modelsHashFile, projFile);
throw;
}
_logger.LogDebug("Done rebuilding.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Done rebuilding.");
}
return assembly;
}
@@ -577,7 +611,10 @@ namespace Umbraco.Cms.Web.Common.ModelsBuilder.InMemoryAuto
private void ClearOnFailingToCompile(string dllPathFile, string modelsHashFile, string projFile)
{
_logger.LogDebug("Failed to compile.");
if (_logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
_logger.LogDebug("Failed to compile.");
}
// the dll file reference still points to the previous dll, which is obsolete
// now and will be deleted by ASP.NET eventually, so better clear that reference.

5
src/Umbraco.Web.Common/Security/MemberSignInManager.cs
View File

@@ -79,10 +79,13 @@ public class MemberSignInManager : UmbracoSignInManager<MemberIdentityUser>, IMe
IDictionary<string, string?>? items = auth.Properties?.Items;
if (auth.Principal == null || items == null)
{
Logger.LogDebug(
if (Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
Logger.LogDebug(
auth.Failure ??
new NullReferenceException("Context.AuthenticateAsync(ExternalAuthenticationType) is null"),
"The external login authentication failed. No user Principal or authentication items was resolved.");
}
return null;
}

5
src/Umbraco.Web.Common/Security/UmbracoSignInManager.cs
View File

@@ -59,8 +59,11 @@ public abstract class UmbracoSignInManager<TUser> : SignInManager<TUser>
IDictionary<string, string?>? items = auth.Properties?.Items;
if (auth.Principal == null || items == null)
{
Logger.LogDebug(
if (Logger.IsEnabled(Microsoft.Extensions.Logging.LogLevel.Debug))
{
Logger.LogDebug(
"The external login authentication failed. No user Principal or authentication items was resolved.");
}
return null;
}