diff --git a/src/Uno.Extensions.Core/Diagnostics/PerformanceTimer.cs b/src/Uno.Extensions.Core/Diagnostics/PerformanceTimer.cs new file mode 100644 index 0000000000..faa963f360 --- /dev/null +++ b/src/Uno.Extensions.Core/Diagnostics/PerformanceTimer.cs @@ -0,0 +1,109 @@ +namespace Uno.Extensions.Diagnostics; + +/// +/// Defines static methods for starting/stopping timers for measuring performance +/// +public static class PerformanceTimer +{ + /// + /// Conditiona compliation symbol to enable performance timers for internal + /// extensions logic. Define constant in Directory.Build.props to enable + /// performance timers eg + /// $(DefineConstants);UNO_EXT_TIMERS + /// Call InitializeTimers from App.xaml.cs, then call Start and Stop + /// to control timers for different scenarios + /// + public const string ConditionalSymbol = "UNO_EXT_TIMERS"; + + private static IDictionary Timers = new Dictionary(); + + private static Action _startAction = static (logger, level, key, caller) => { }; + private static Func _splitAction = static (key) => TimeSpan.Zero; + private static Func _stopAction = static (logger, level, key, caller) => TimeSpan.Zero; + + /// + /// Initializes performance timing methods. Make sure you also define the + /// UNO_EXT_TIMERS constant to prevent this method from being removed during compilation + /// + [Conditional(ConditionalSymbol)] + public static void InitializeTimers() + { + _startAction = InternalStart; + _splitAction = InternalSplit; + _stopAction = InternalStop; + } + + /// + /// Start a timer + /// + /// Logger to output start message to + /// LogLevel to output start message at + /// Unique identifier for timer + /// The method calling the start method + public static void Start(ILogger logger, LogLevel level, Guid key, [CallerMemberName] string caller = "") => _startAction(logger, level, key, caller); + + /// + /// Returns an in-progress timespan for the specified timer + /// + /// The unique identifier for the timer + /// Elapsed time since timer was started + public static TimeSpan Split(Guid key) => _splitAction(key); + + /// + /// Stops a timer + /// + /// Logger to output stop message to + /// LogLevel to output stop message at + /// Unique identifier for timer + /// The method calling the stop method + /// Elapsed time since timer was started + public static TimeSpan Stop(ILogger logger, LogLevel level, Guid key, [CallerMemberName] string caller = "") => _stopAction(logger, level, key, caller); + + + private static void InternalStart(ILogger logger, LogLevel level, Guid key, [CallerMemberName] string caller = "") + { + var timer = new Stopwatch(); + timer.Start(); + Timers[key] = timer; + if (logger?.IsEnabled(level) ?? false) + { + logger.Log(level, $"[{key}:{caller}] Start"); + } + } + + + private static TimeSpan InternalSplit(Guid key) + { + if (Timers.TryGetValue(key, out var timer)) + { + return timer.Elapsed; + } + else + { + return TimeSpan.Zero; + } + } + + private static TimeSpan InternalStop(ILogger logger, LogLevel level, Guid key, [CallerMemberName] string caller = "") + { + if (Timers.TryGetValue(key, out var timer)) + { + Timers.Remove(key); + timer.Stop(); + if (logger?.IsEnabled(level) ?? false) + { + logger.Log(level, $"[{key}:{caller}] {timer.ElapsedMilliseconds}ms"); + } + return timer.Elapsed; + } + else + { + if (logger?.IsEnabled(level) ?? false) + { + logger.Log(level, $"[{key}:{caller}] MISSING - Either Start hasn't been called, or Stop has already been called"); + } + return TimeSpan.Zero; + } + + } +} diff --git a/src/Uno.Extensions.Core/GlobalUsings.cs b/src/Uno.Extensions.Core/GlobalUsings.cs index 9820b6399d..b29be24225 100644 --- a/src/Uno.Extensions.Core/GlobalUsings.cs +++ b/src/Uno.Extensions.Core/GlobalUsings.cs @@ -1,6 +1,8 @@ global using System; global using System.Collections.Generic; +global using System.Diagnostics; global using System.Linq; +global using System.Runtime.CompilerServices; global using System.Runtime.InteropServices; global using System.Threading; global using System.Threading.Tasks; @@ -9,4 +11,3 @@ global using Microsoft.Extensions.Logging; global using Uno.Extensions.DependencyInjection; - diff --git a/src/Uno.Extensions.Navigation.UI/IRouteUpdater.cs b/src/Uno.Extensions.Navigation.UI/IRouteUpdater.cs index ba0e3b048b..c1ad56a6d7 100644 --- a/src/Uno.Extensions.Navigation.UI/IRouteUpdater.cs +++ b/src/Uno.Extensions.Navigation.UI/IRouteUpdater.cs @@ -2,8 +2,8 @@ internal interface IRouteUpdater { - Guid StartNavigation(IRegion region); + void StartNavigation(INavigator navigator, IRegion region, NavigationRequest request); - Task EndNavigation(Guid regionUpdateId); + void EndNavigation(INavigator navigator, IRegion region, NavigationRequest request); } diff --git a/src/Uno.Extensions.Navigation.UI/Navigator.cs b/src/Uno.Extensions.Navigation.UI/Navigator.cs index ba5dcceec1..9f8556ce79 100644 --- a/src/Uno.Extensions.Navigation.UI/Navigator.cs +++ b/src/Uno.Extensions.Navigation.UI/Navigator.cs @@ -9,7 +9,7 @@ public class Navigator : INavigator, IInstance protected IRegion Region { get; } - private IRouteUpdater? RouteUpdater => Region.Services?.GetRequiredService(); + private IRouteUpdater RouteUpdater => Region.Services!.GetRequiredService(); IServiceProvider? IInstance.Instance => Region.Services; @@ -42,7 +42,7 @@ protected Navigator( public async Task NavigateAsync(NavigationRequest request) { - var regionUpdateId = RouteUpdater?.StartNavigation(Region) ?? Guid.Empty; + RouteUpdater.StartNavigation(this, Region, request); try { @@ -60,6 +60,9 @@ protected Navigator( request = request with { Source = this }; } +#if !WASM + Debug.Assert(!Dispatcher.HasThreadAccess, "Navigation should be running on background thread"); +#endif if (Logger.IsEnabled(LogLevel.Debug)) Logger.LogDebugMessage($" Navigator: {this.GetType().Name} Request: {request.Route}"); @@ -94,10 +97,7 @@ protected Navigator( } finally { - if (RouteUpdater is { } routeUpdater) - { - await routeUpdater.EndNavigation(regionUpdateId); - } + RouteUpdater.EndNavigation(this, Region, request); } } diff --git a/src/Uno.Extensions.Navigation.UI/Regions/RegionExtensions.cs b/src/Uno.Extensions.Navigation.UI/Regions/RegionExtensions.cs index 7ad2c59e2d..0416ea42d8 100644 --- a/src/Uno.Extensions.Navigation.UI/Regions/RegionExtensions.cs +++ b/src/Uno.Extensions.Navigation.UI/Regions/RegionExtensions.cs @@ -12,14 +12,16 @@ public static Task CanNavigate(this IRegion region, Route route) public static Task NavigateAsync(this IRegion region, NavigationRequest request) => (region.Navigator()?.NavigateAsync(request)) ?? Task.FromResult(default); - public static bool IsUnnamed(this IRegion region, Route? parentRoute=null) => + public static bool IsUnnamed(this IRegion region, Route? parentRoute = null) => string.IsNullOrEmpty(region.Name) || (region.Name == parentRoute?.Base); // Where an un-named region is nested, the name is updated to the current route - public static IRegion Root(this IRegion region) - { - return region.Parent is not null ? region.Parent.Root() : region; - } + /// + /// Returns the root region at the top of the region hierarchy + /// + /// The start point of the hierarchy search + /// The root region + public static IRegion Root(this IRegion region) => region.Parent?.Root() ?? region; internal static (Route?, IRegion, INavigator?)[] Ancestors( this IRegion region, diff --git a/src/Uno.Extensions.Navigation.UI/RouteNotifier.cs b/src/Uno.Extensions.Navigation.UI/RouteNotifier.cs index 31a5d96798..0044374a0b 100644 --- a/src/Uno.Extensions.Navigation.UI/RouteNotifier.cs +++ b/src/Uno.Extensions.Navigation.UI/RouteNotifier.cs @@ -1,4 +1,5 @@ using System.Diagnostics; +using Uno.Extensions.Diagnostics; using Uno.Extensions.Logging; namespace Uno.Extensions.Navigation; @@ -13,48 +14,46 @@ public RouteNotifier(ILogger logger) Logger = logger; } - private IDictionary regionRoots= new Dictionary(); - private IDictionary runningNavigations = new Dictionary(); - private IDictionary timers = new Dictionary(); + private IDictionary navigationSegments = new Dictionary(); + private IDictionary runningNavigations = new Dictionary(); - public Guid StartNavigation(IRegion region) - { - var regionUpdateId = Guid.NewGuid(); - var root = region.Root(); - regionRoots[regionUpdateId] = root; - if (!runningNavigations.TryGetValue(root, out var count) || + public void StartNavigation(INavigator navigator, IRegion region, NavigationRequest request) + { + var id = request.Id; + if (!runningNavigations.TryGetValue(id, out var count) || count == 0) { - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTraceMessage($"Pre-navigation: - {root.ToString()}"); - runningNavigations[root] = 1; - var timer = new Stopwatch(); - timers[root] = timer; - timer.Start(); + runningNavigations[id] = 1; + navigationSegments[id] = new StringBuilder(); + navigationSegments[id].AppendLine($"[{id}] Navigation Start"); + PerformanceTimer.Start(Logger, LogLevel.Trace, id); } else { - runningNavigations[root] = runningNavigations[root] + 1; - timers[root].Restart(); + runningNavigations[id] = runningNavigations[id] + 1; + } + if (Logger.IsEnabled(LogLevel.Trace)) + { + navigationSegments[id].AppendLine($"[{id} - {PerformanceTimer.Split(id).TotalMilliseconds}] {navigator.GetType().Name} - {region.Name??"unnamed"} - {request.Route} {(request.Route.IsInternal?"(internal)":"")}"); } - - return regionUpdateId; } - public async Task EndNavigation(Guid regionUpdateId) + public void EndNavigation(INavigator navigator, IRegion region, NavigationRequest request) { - var root= regionRoots[regionUpdateId]; - regionRoots.Remove(regionUpdateId); - runningNavigations[root] = runningNavigations[root] - 1; + var id = request.Id; + runningNavigations[id] = runningNavigations[id] - 1; - if (runningNavigations[root] == 0) + if (runningNavigations[id] == 0) { - timers[root].Stop(); - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTraceMessage($"Elapsed navigation: {timers[root].ElapsedMilliseconds}"); - if (Logger.IsEnabled(LogLevel.Trace) && root is NavigationRegion navRegion) Logger.LogTraceMessage($"Post-navigation: {await navRegion.GetStringAsync()}"); - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTraceMessage($"Post-navigation (route): {root.GetRoute()}"); - - RouteChanged?.Invoke(this, new RouteChangedEventArgs(root)); + var elapsed = PerformanceTimer.Stop(Logger, LogLevel.Trace, id); + if (Logger.IsEnabled(LogLevel.Trace)) + { + navigationSegments[id].AppendLine($"[{id} - {elapsed.TotalMilliseconds}] Navigation End"); + Logger.LogTraceMessage($"Post-navigation (summary):\n{navigationSegments[id]}"); + } + navigationSegments.Remove(id); + RouteChanged?.Invoke(this, new RouteChangedEventArgs(region.Root())); } } } diff --git a/src/Uno.Extensions.Navigation/NavigationRequest.cs b/src/Uno.Extensions.Navigation/NavigationRequest.cs index 24f27a10c3..eaac8fd677 100644 --- a/src/Uno.Extensions.Navigation/NavigationRequest.cs +++ b/src/Uno.Extensions.Navigation/NavigationRequest.cs @@ -4,6 +4,8 @@ public record NavigationRequest(object Sender, Route Route, CancellationToken? Cancellation = default, Type? Result = null, INavigator? Source = null) #pragma warning restore SA1313 // Parameter names should begin with lower-case letter { + internal Guid Id { get; } = Guid.NewGuid(); + internal bool InProgress { get; init; } public override string ToString() => $"Request [Sender: {Sender.GetType().Name}, Route:{Route}, Result: {Result?.Name ?? "N/A"}]"; diff --git a/testing/TestHarness/Directory.Build.props b/testing/TestHarness/Directory.Build.props index e8fd3e53ec..2b337c8de0 100644 --- a/testing/TestHarness/Directory.Build.props +++ b/testing/TestHarness/Directory.Build.props @@ -5,6 +5,14 @@ $(NoWarn);NU5104;NU1504;NU1505;CS1591;MSB3277;XA0101;CS8785;CS8669;CA1416 true true + + + + + + + + diff --git a/testing/TestHarness/TestHarness.Shared/BaseHostInitialization.cs b/testing/TestHarness/TestHarness.Shared/BaseHostInitialization.cs index 1cf60f3535..f1a6115556 100644 --- a/testing/TestHarness/TestHarness.Shared/BaseHostInitialization.cs +++ b/testing/TestHarness/TestHarness.Shared/BaseHostInitialization.cs @@ -84,7 +84,7 @@ protected virtual IHostBuilder Logging(IHostBuilder builder) { var host = context.HostingEnvironment; // Configure log levels for different categories of logging - logBuilder.SetMinimumLevel(host.IsDevelopment() ? LogLevel.Warning : LogLevel.Warning); + logBuilder.SetMinimumLevel(host.IsDevelopment() ? LogLevel.Trace : LogLevel.Warning); }); } diff --git a/testing/TestHarness/TestHarness.Shared/BaseTestSectionPage.cs b/testing/TestHarness/TestHarness.Shared/BaseTestSectionPage.cs index 1c68f9e2cf..0dc4578f40 100644 --- a/testing/TestHarness/TestHarness.Shared/BaseTestSectionPage.cs +++ b/testing/TestHarness/TestHarness.Shared/BaseTestSectionPage.cs @@ -1,5 +1,6 @@  +using Uno.Extensions.Diagnostics; using Uno.Toolkit.UI; namespace TestHarness; @@ -10,6 +11,7 @@ public partial class BaseTestSectionPage : Page, IDisposable public BaseTestSectionPage() { + PerformanceTimer.InitializeTimers(); Loaded += BaseTestSectionPage_Loaded; }