From 10ad8c8baaaf2ede0a653efe63e314d7761204be Mon Sep 17 00:00:00 2001 From: Sebastian Date: Sun, 13 May 2018 09:38:32 +0200 Subject: [PATCH] Profiler simplified. --- Squidex.sln | 2 +- .../AppProvider.cs | 18 ++--- .../Caching/AsyncLocalCache.cs | 30 +++----- ...ssionProvider.cs => DelegateDisposable.cs} | 20 +++++- src/Squidex.Infrastructure/Log/Profile.cs | 67 ------------------ src/Squidex.Infrastructure/Log/Profiler.cs | 69 +++++++++++++++++++ .../Log/SemanticLogExtensions.cs | 45 +++++------- src/Squidex.Infrastructure/Orleans/J{T}.cs | 4 +- .../Orleans/LocalCacheFilter.cs | 10 ++- .../Tasks/AsyncLocalCleaner.cs | 29 ++++++++ src/Squidex/Config/Domain/LoggingServices.cs | 4 -- src/Squidex/Pipeline/ApiCostsFilter.cs | 2 +- .../RequestLogPerformanceMiddleware.cs | 34 ++++----- .../RequestLogProfilerSessionProvider.cs | 40 ----------- 14 files changed, 177 insertions(+), 197 deletions(-) rename src/Squidex.Infrastructure/{Log/ILogProfilerSessionProvider.cs => DelegateDisposable.cs} (50%) delete mode 100644 src/Squidex.Infrastructure/Log/Profile.cs create mode 100644 src/Squidex.Infrastructure/Log/Profiler.cs create mode 100644 src/Squidex.Infrastructure/Tasks/AsyncLocalCleaner.cs delete mode 100644 src/Squidex/Pipeline/RequestLogProfilerSessionProvider.cs diff --git a/Squidex.sln b/Squidex.sln index 67ffac379..f3c7e803d 100644 --- a/Squidex.sln +++ b/Squidex.sln @@ -335,7 +335,7 @@ Global {C1E5BBB6-6B6A-4DE5-B19D-0538304DE343} = {8CF53B92-5EB1-461D-98F8-70DA9B603FBF} {945871B1-77B8-43FB-B53C-27CF385AB756} = {8CF53B92-5EB1-461D-98F8-70DA9B603FBF} {B51126A8-0D75-4A79-867D-10724EC6AC84} = {94207AA6-4923-4183-A558-E0F8196B8CA3} - {5E75AB7D-6F01-4313-AFF1-7F7128FFD71F} = {4C6B06C2-6D77-4E0E-AE32-D7050236433A} + {5E75AB7D-6F01-4313-AFF1-7F7128FFD71F} = {8CF53B92-5EB1-461D-98F8-70DA9B603FBF} {C9809D59-6665-471E-AD87-5AC624C65892} = {4C6B06C2-6D77-4E0E-AE32-D7050236433A} {C0D540F0-9158-4528-BFD8-BEAE6EAE45EA} = {4C6B06C2-6D77-4E0E-AE32-D7050236433A} {F7771E22-47BD-45C4-A133-FD7F1DE27CA0} = {C0D540F0-9158-4528-BFD8-BEAE6EAE45EA} diff --git a/src/Squidex.Domain.Apps.Entities/AppProvider.cs b/src/Squidex.Domain.Apps.Entities/AppProvider.cs index 1a34f532b..b0f8870a9 100644 --- a/src/Squidex.Domain.Apps.Entities/AppProvider.cs +++ b/src/Squidex.Domain.Apps.Entities/AppProvider.cs @@ -38,7 +38,7 @@ namespace Squidex.Domain.Apps.Entities { return localCache.GetOrCreateAsync($"GetAppWithSchemaAsync({appId}, {id})", async () => { - using (Profile.Method()) + using (Profiler.TraceMethod()) { var app = await grainFactory.GetGrain(appId).GetStateAsync(); @@ -63,7 +63,7 @@ namespace Squidex.Domain.Apps.Entities { return localCache.GetOrCreateAsync($"GetAppAsync({appName})", async () => { - using (Profile.Method()) + using (Profiler.TraceMethod()) { var appId = await GetAppIdAsync(appName); @@ -88,7 +88,7 @@ namespace Squidex.Domain.Apps.Entities { return localCache.GetOrCreateAsync($"GetSchemaAsync({appId}, {name})", async () => { - using (Profile.Method()) + using (Profiler.TraceMethod()) { var schemaId = await GetSchemaIdAsync(appId, name); @@ -106,7 +106,7 @@ namespace Squidex.Domain.Apps.Entities { return localCache.GetOrCreateAsync($"GetSchemaAsync({appId}, {id}, {allowDeleted})", async () => { - using (Profile.Method()) + using (Profiler.TraceMethod()) { var schema = await grainFactory.GetGrain(id).GetStateAsync(); @@ -124,7 +124,7 @@ namespace Squidex.Domain.Apps.Entities { return localCache.GetOrCreateAsync($"GetSchemasAsync({appId})", async () => { - using (Profile.Method()) + using (Profiler.TraceMethod()) { var ids = await grainFactory.GetGrain(appId).GetSchemaIdsAsync(); @@ -141,7 +141,7 @@ namespace Squidex.Domain.Apps.Entities { return localCache.GetOrCreateAsync($"GetRulesAsync({appId})", async () => { - using (Profile.Method()) + using (Profiler.TraceMethod()) { var ids = await grainFactory.GetGrain(appId).GetRuleIdsAsync(); @@ -158,7 +158,7 @@ namespace Squidex.Domain.Apps.Entities { return localCache.GetOrCreateAsync($"GetUserApps({userId})", async () => { - using (Profile.Method()) + using (Profiler.TraceMethod()) { var ids = await grainFactory.GetGrain(userId).GetAppIdsAsync(); @@ -173,7 +173,7 @@ namespace Squidex.Domain.Apps.Entities private async Task GetAppIdAsync(string name) { - using (Profile.Method()) + using (Profiler.TraceMethod()) { return await grainFactory.GetGrain(SingleGrain.Id).GetAppIdAsync(name); } @@ -181,7 +181,7 @@ namespace Squidex.Domain.Apps.Entities private async Task GetSchemaIdAsync(Guid appId, string name) { - using (Profile.Method()) + using (Profiler.TraceMethod()) { return await grainFactory.GetGrain(appId).GetSchemaIdAsync(name); } diff --git a/src/Squidex.Infrastructure/Caching/AsyncLocalCache.cs b/src/Squidex.Infrastructure/Caching/AsyncLocalCache.cs index 7156a6c06..e892a4019 100644 --- a/src/Squidex.Infrastructure/Caching/AsyncLocalCache.cs +++ b/src/Squidex.Infrastructure/Caching/AsyncLocalCache.cs @@ -8,37 +8,23 @@ using System; using System.Collections.Concurrent; using System.Threading; +using Squidex.Infrastructure.Tasks; namespace Squidex.Infrastructure.Caching { public sealed class AsyncLocalCache : ILocalCache { - private static readonly AsyncLocal> Cache = new AsyncLocal>(); - private static readonly AsyncLocalCleaner Cleaner; - - private sealed class AsyncLocalCleaner : IDisposable - { - private readonly AsyncLocal> cache; - - public AsyncLocalCleaner(AsyncLocal> cache) - { - this.cache = cache; - } - - public void Dispose() - { - cache.Value = null; - } - } + private static readonly AsyncLocal> LocalCache = new AsyncLocal>(); + private static readonly AsyncLocalCleaner> Cleaner; static AsyncLocalCache() { - Cleaner = new AsyncLocalCleaner(Cache); + Cleaner = new AsyncLocalCleaner>(LocalCache); } public IDisposable StartContext() { - Cache.Value = new ConcurrentDictionary(); + LocalCache.Value = new ConcurrentDictionary(); return Cleaner; } @@ -47,7 +33,7 @@ namespace Squidex.Infrastructure.Caching { var cacheKey = GetCacheKey(key); - var cache = Cache.Value; + var cache = LocalCache.Value; if (cache != null) { @@ -59,7 +45,7 @@ namespace Squidex.Infrastructure.Caching { var cacheKey = GetCacheKey(key); - var cache = Cache.Value; + var cache = LocalCache.Value; if (cache != null) { @@ -71,7 +57,7 @@ namespace Squidex.Infrastructure.Caching { var cacheKey = GetCacheKey(key); - var cache = Cache.Value; + var cache = LocalCache.Value; if (cache != null) { diff --git a/src/Squidex.Infrastructure/Log/ILogProfilerSessionProvider.cs b/src/Squidex.Infrastructure/DelegateDisposable.cs similarity index 50% rename from src/Squidex.Infrastructure/Log/ILogProfilerSessionProvider.cs rename to src/Squidex.Infrastructure/DelegateDisposable.cs index a0b2d8a16..bbdbb0262 100644 --- a/src/Squidex.Infrastructure/Log/ILogProfilerSessionProvider.cs +++ b/src/Squidex.Infrastructure/DelegateDisposable.cs @@ -5,10 +5,24 @@ // All rights reserved. Licensed under the MIT license. // ========================================================================== -namespace Squidex.Infrastructure.Log +using System; + +namespace Squidex.Infrastructure { - public interface ILogProfilerSessionProvider + public sealed class DelegateDisposable : IDisposable { - ProfilerSession GetSession(); + private readonly Action action; + + public DelegateDisposable(Action action) + { + Guard.NotNull(action, nameof(action)); + + this.action = action; + } + + public void Dispose() + { + action(); + } } } diff --git a/src/Squidex.Infrastructure/Log/Profile.cs b/src/Squidex.Infrastructure/Log/Profile.cs deleted file mode 100644 index ce7cc058c..000000000 --- a/src/Squidex.Infrastructure/Log/Profile.cs +++ /dev/null @@ -1,67 +0,0 @@ -// ========================================================================== -// Squidex Headless CMS -// ========================================================================== -// Copyright (c) Squidex UG (haftungsbeschraenkt) -// All rights reserved. Licensed under the MIT license. -// ========================================================================== - -using System; -using System.Diagnostics; -using System.Runtime.CompilerServices; - -namespace Squidex.Infrastructure.Log -{ - public static class Profile - { - private static ILogProfilerSessionProvider sessionProvider; - - private sealed class Timer : IDisposable - { - private readonly Stopwatch watch = Stopwatch.StartNew(); - private readonly ProfilerSession session; - private readonly string key; - - public Timer(ProfilerSession session, string key) - { - this.session = session; - this.key = key; - } - - public void Dispose() - { - watch.Stop(); - - session.Measured(key, watch.ElapsedMilliseconds); - } - } - - public static void Init(ILogProfilerSessionProvider provider) - { - sessionProvider = provider; - } - - public static IDisposable Method([CallerMemberName] string memberName = null) - { - return Key($"{typeof(T).Name}/{memberName}"); - } - - public static IDisposable Method(string objectName, [CallerMemberName] string memberName = null) - { - return Key($"{objectName}/{memberName}"); - } - - public static IDisposable Key(string key) - { - Guard.NotNull(key, nameof(key)); - - var session = sessionProvider?.GetSession(); - - if (session == null) - { - return NoopDisposable.Instance; - } - - return new Timer(session, key); - } - } -} diff --git a/src/Squidex.Infrastructure/Log/Profiler.cs b/src/Squidex.Infrastructure/Log/Profiler.cs new file mode 100644 index 000000000..2f4a83fe3 --- /dev/null +++ b/src/Squidex.Infrastructure/Log/Profiler.cs @@ -0,0 +1,69 @@ +// ========================================================================== +// Squidex Headless CMS +// ========================================================================== +// Copyright (c) Squidex UG (haftungsbeschraenkt) +// All rights reserved. Licensed under the MIT license. +// ========================================================================== + +using System; +using System.Diagnostics; +using System.Runtime.CompilerServices; +using System.Threading; +using Squidex.Infrastructure.Tasks; + +namespace Squidex.Infrastructure.Log +{ + public static class Profiler + { + private static readonly AsyncLocal LocalSession = new AsyncLocal(); + private static readonly AsyncLocalCleaner Cleaner; + + public static ProfilerSession Session + { + get { return LocalSession.Value; } + } + + static Profiler() + { + Cleaner = new AsyncLocalCleaner(LocalSession); + } + + public static IDisposable StartSession() + { + LocalSession.Value = new ProfilerSession(); + + return Cleaner; + } + + public static IDisposable TraceMethod([CallerMemberName] string memberName = null) + { + return Trace($"{typeof(T).Name}/{memberName}"); + } + + public static IDisposable TraceMethod(string objectName, [CallerMemberName] string memberName = null) + { + return Trace($"{objectName}/{memberName}"); + } + + public static IDisposable Trace(string key) + { + Guard.NotNull(key, nameof(key)); + + var session = LocalSession.Value; + + if (session == null) + { + return NoopDisposable.Instance; + } + + var watch = Stopwatch.StartNew(); + + return new DelegateDisposable(() => + { + watch.Stop(); + + session.Measured(key, watch.ElapsedMilliseconds); + }); + } + } +} diff --git a/src/Squidex.Infrastructure/Log/SemanticLogExtensions.cs b/src/Squidex.Infrastructure/Log/SemanticLogExtensions.cs index a10acea8c..f36ef6d7d 100644 --- a/src/Squidex.Infrastructure/Log/SemanticLogExtensions.cs +++ b/src/Squidex.Infrastructure/Log/SemanticLogExtensions.cs @@ -17,31 +17,16 @@ namespace Squidex.Infrastructure.Log log.Log(SemanticLogLevel.Trace, objectWriter); } - public static IDisposable MeasureTrace(this ISemanticLog log, Action objectWriter) - { - return new TimeMeasurer(log, SemanticLogLevel.Trace, objectWriter); - } - public static void LogDebug(this ISemanticLog log, Action objectWriter) { log.Log(SemanticLogLevel.Debug, objectWriter); } - public static IDisposable MeasureDebug(this ISemanticLog log, Action objectWriter) - { - return new TimeMeasurer(log, SemanticLogLevel.Debug, objectWriter); - } - public static void LogInformation(this ISemanticLog log, Action objectWriter) { log.Log(SemanticLogLevel.Information, objectWriter); } - public static IDisposable MeasureInformation(this ISemanticLog log, Action objectWriter) - { - return new TimeMeasurer(log, SemanticLogLevel.Information, objectWriter); - } - public static void LogWarning(this ISemanticLog log, Action objectWriter) { log.Log(SemanticLogLevel.Warning, objectWriter); @@ -92,22 +77,26 @@ namespace Squidex.Infrastructure.Log }); } - private sealed class TimeMeasurer : IDisposable + public static IDisposable MeasureTrace(this ISemanticLog log, Action objectWriter) + { + return log.Measure(SemanticLogLevel.Trace, objectWriter); + } + + public static IDisposable MeasureDebug(this ISemanticLog log, Action objectWriter) { - private readonly Stopwatch watch = Stopwatch.StartNew(); - private readonly SemanticLogLevel logLevel; - private readonly Action objectWriter; - private readonly ISemanticLog log; + return log.Measure(SemanticLogLevel.Debug, objectWriter); + } - public TimeMeasurer(ISemanticLog log, SemanticLogLevel logLevel, Action objectWriter) - { - this.logLevel = logLevel; - this.log = log; + public static IDisposable MeasureInformation(this ISemanticLog log, Action objectWriter) + { + return log.Measure(SemanticLogLevel.Information, objectWriter); + } - this.objectWriter = objectWriter; - } + private static IDisposable Measure(this ISemanticLog log, SemanticLogLevel logLevel, Action objectWriter) + { + var watch = Stopwatch.StartNew(); - public void Dispose() + return new DelegateDisposable(() => { watch.Stop(); @@ -117,7 +106,7 @@ namespace Squidex.Infrastructure.Log writer.WriteProperty("elapsedMs", watch.ElapsedMilliseconds); }); - } + }); } } } diff --git a/src/Squidex.Infrastructure/Orleans/J{T}.cs b/src/Squidex.Infrastructure/Orleans/J{T}.cs index 374b94dd1..a85c29dd4 100644 --- a/src/Squidex.Infrastructure/Orleans/J{T}.cs +++ b/src/Squidex.Infrastructure/Orleans/J{T}.cs @@ -55,7 +55,7 @@ namespace Squidex.Infrastructure.Orleans [SerializerMethod] public static void Serialize(object input, ISerializationContext context, Type expected) { - using (Profile.Method(nameof(J))) + using (Profiler.TraceMethod(nameof(J))) { var jsonSerializer = GetSerializer(context); @@ -78,7 +78,7 @@ namespace Squidex.Infrastructure.Orleans [DeserializerMethod] public static object Deserialize(Type expected, IDeserializationContext context) { - using (Profile.Method(nameof(J))) + using (Profiler.TraceMethod(nameof(J))) { var jsonSerializer = GetSerializer(context); diff --git a/src/Squidex.Infrastructure/Orleans/LocalCacheFilter.cs b/src/Squidex.Infrastructure/Orleans/LocalCacheFilter.cs index 7a49d31cf..842a0dad9 100644 --- a/src/Squidex.Infrastructure/Orleans/LocalCacheFilter.cs +++ b/src/Squidex.Infrastructure/Orleans/LocalCacheFilter.cs @@ -5,6 +5,7 @@ // All rights reserved. Licensed under the MIT license. // ========================================================================== +using System; using System.Threading.Tasks; using Orleans; using Squidex.Infrastructure.Caching; @@ -24,7 +25,14 @@ namespace Squidex.Infrastructure.Orleans public async Task Invoke(IIncomingGrainCallContext context) { - using (localCache.StartContext()) + if (!context.Grain.GetType().Namespace.StartsWith("Orleans", StringComparison.OrdinalIgnoreCase)) + { + using (localCache.StartContext()) + { + await context.Invoke(); + } + } + else { await context.Invoke(); } diff --git a/src/Squidex.Infrastructure/Tasks/AsyncLocalCleaner.cs b/src/Squidex.Infrastructure/Tasks/AsyncLocalCleaner.cs new file mode 100644 index 000000000..0a38e5194 --- /dev/null +++ b/src/Squidex.Infrastructure/Tasks/AsyncLocalCleaner.cs @@ -0,0 +1,29 @@ +// ========================================================================== +// Squidex Headless CMS +// ========================================================================== +// Copyright (c) Squidex UG (haftungsbeschraenkt) +// All rights reserved. Licensed under the MIT license. +// ========================================================================== + +using System; +using System.Threading; + +namespace Squidex.Infrastructure.Tasks +{ + public sealed class AsyncLocalCleaner : IDisposable + { + private readonly AsyncLocal asyncLocal; + + public AsyncLocalCleaner(AsyncLocal asyncLocal) + { + Guard.NotNull(asyncLocal, nameof(asyncLocal)); + + this.asyncLocal = asyncLocal; + } + + public void Dispose() + { + asyncLocal.Value = default(T); + } + } +} diff --git a/src/Squidex/Config/Domain/LoggingServices.cs b/src/Squidex/Config/Domain/LoggingServices.cs index 6306018b9..e4ee51850 100644 --- a/src/Squidex/Config/Domain/LoggingServices.cs +++ b/src/Squidex/Config/Domain/LoggingServices.cs @@ -59,10 +59,6 @@ namespace Squidex.Config.Domain services.AddSingletonAs() .As(); - - services.AddSingletonAs() - .As() - .AsSelf(); } } } diff --git a/src/Squidex/Pipeline/ApiCostsFilter.cs b/src/Squidex/Pipeline/ApiCostsFilter.cs index a4161e29c..ff5dc0aea 100644 --- a/src/Squidex/Pipeline/ApiCostsFilter.cs +++ b/src/Squidex/Pipeline/ApiCostsFilter.cs @@ -48,7 +48,7 @@ namespace Squidex.Pipeline if (appFeature?.App != null && FilterDefinition.Weight > 0) { - using (Profile.Key("CheckUsage")) + using (Profiler.Trace("CheckUsage")) { var plan = appPlanProvider.GetPlanForApp(appFeature.App); diff --git a/src/Squidex/Pipeline/RequestLogPerformanceMiddleware.cs b/src/Squidex/Pipeline/RequestLogPerformanceMiddleware.cs index e7afe2c16..0edc2306c 100644 --- a/src/Squidex/Pipeline/RequestLogPerformanceMiddleware.cs +++ b/src/Squidex/Pipeline/RequestLogPerformanceMiddleware.cs @@ -14,13 +14,10 @@ namespace Squidex.Pipeline { public sealed class RequestLogPerformanceMiddleware : IMiddleware { - private readonly RequestLogProfilerSessionProvider requestSession; private readonly ISemanticLog log; - public RequestLogPerformanceMiddleware(RequestLogProfilerSessionProvider requestSession, ISemanticLog log) + public RequestLogPerformanceMiddleware(ISemanticLog log) { - this.requestSession = requestSession; - this.log = log; } @@ -28,24 +25,23 @@ namespace Squidex.Pipeline { var stopWatch = Stopwatch.StartNew(); - var session = new ProfilerSession(); - - try - { - requestSession.Start(context, session); - - await next(context); - } - finally + using (Profiler.StartSession()) { - stopWatch.Stop(); - - log.LogInformation(w => + try { - session.Write(w); + await next(context); + } + finally + { + stopWatch.Stop(); + + log.LogInformation(w => + { + Profiler.Session?.Write(w); - w.WriteProperty("elapsedRequestMs", stopWatch.ElapsedMilliseconds); - }); + w.WriteProperty("elapsedRequestMs", stopWatch.ElapsedMilliseconds); + }); + } } } } diff --git a/src/Squidex/Pipeline/RequestLogProfilerSessionProvider.cs b/src/Squidex/Pipeline/RequestLogProfilerSessionProvider.cs deleted file mode 100644 index d4805f663..000000000 --- a/src/Squidex/Pipeline/RequestLogProfilerSessionProvider.cs +++ /dev/null @@ -1,40 +0,0 @@ -// ========================================================================== -// Squidex Headless CMS -// ========================================================================== -// Copyright (c) Squidex UG (haftungsbeschraenkt) -// All rights reserved. Licensed under the MIT license. -// ========================================================================== - -using Microsoft.AspNetCore.Http; -using Squidex.Infrastructure; -using Squidex.Infrastructure.Log; - -namespace Squidex.Pipeline -{ - public sealed class RequestLogProfilerSessionProvider : ILogProfilerSessionProvider - { - private const string ItemKey = "ProfilerSesison"; - private readonly IHttpContextAccessor httpContextAccessor; - - public RequestLogProfilerSessionProvider(IHttpContextAccessor httpContextAccessor) - { - this.httpContextAccessor = httpContextAccessor; - - Profile.Init(this); - } - - public ProfilerSession GetSession() - { - var context = httpContextAccessor?.HttpContext?.Items[ItemKey] as ProfilerSession; - - return context; - } - - public void Start(HttpContext httpContext, ProfilerSession session) - { - Guard.NotNull(httpContext, nameof(httpContext)); - - httpContext.Items[ItemKey] = session; - } - } -}