Skip to content

Commit

Permalink
Merge pull request #901 from unoplatform/dev/nr/perftimer
Browse files Browse the repository at this point in the history
feat: Adding performance timers to navigation
  • Loading branch information
nickrandolph authored Nov 10, 2022
2 parents b9ac2bf + 163afad commit eabda02
Show file tree
Hide file tree
Showing 10 changed files with 167 additions and 44 deletions.
109 changes: 109 additions & 0 deletions src/Uno.Extensions.Core/Diagnostics/PerformanceTimer.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,109 @@
namespace Uno.Extensions.Diagnostics;

/// <summary>
/// Defines static methods for starting/stopping timers for measuring performance
/// </summary>
public static class PerformanceTimer
{
/// <summary>
/// Conditiona compliation symbol to enable performance timers for internal
/// extensions logic. Define constant in Directory.Build.props to enable
/// performance timers eg
/// <DefineConstants>$(DefineConstants);UNO_EXT_TIMERS</DefineConstants>
/// Call InitializeTimers from App.xaml.cs, then call Start and Stop
/// to control timers for different scenarios
/// </summary>
public const string ConditionalSymbol = "UNO_EXT_TIMERS";

private static IDictionary<Guid, Stopwatch> Timers = new Dictionary<Guid, Stopwatch>();

private static Action<ILogger, LogLevel, Guid, string> _startAction = static (logger, level, key, caller) => { };
private static Func<Guid, TimeSpan> _splitAction = static (key) => TimeSpan.Zero;
private static Func<ILogger, LogLevel, Guid, string, TimeSpan> _stopAction = static (logger, level, key, caller) => TimeSpan.Zero;

/// <summary>
/// Initializes performance timing methods. Make sure you also define the
/// UNO_EXT_TIMERS constant to prevent this method from being removed during compilation
/// </summary>
[Conditional(ConditionalSymbol)]
public static void InitializeTimers()
{
_startAction = InternalStart;
_splitAction = InternalSplit;
_stopAction = InternalStop;
}

/// <summary>
/// Start a timer
/// </summary>
/// <param name="logger">Logger to output start message to</param>
/// <param name="level">LogLevel to output start message at</param>
/// <param name="key">Unique identifier for timer</param>
/// <param name="caller">The method calling the start method</param>
public static void Start(ILogger logger, LogLevel level, Guid key, [CallerMemberName] string caller = "") => _startAction(logger, level, key, caller);

/// <summary>
/// Returns an in-progress timespan for the specified timer
/// </summary>
/// <param name="key">The unique identifier for the timer</param>
/// <returns>Elapsed time since timer was started</returns>
public static TimeSpan Split(Guid key) => _splitAction(key);

/// <summary>
/// Stops a timer
/// </summary>
/// <param name="logger">Logger to output stop message to</param>
/// <param name="level">LogLevel to output stop message at</param>
/// <param name="key">Unique identifier for timer</param>
/// <param name="caller">The method calling the stop method</param>
/// <returns>Elapsed time since timer was started</returns>
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;
}

}
}
3 changes: 2 additions & 1 deletion src/Uno.Extensions.Core/GlobalUsings.cs
Original file line number Diff line number Diff line change
@@ -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;
Expand All @@ -9,4 +11,3 @@
global using Microsoft.Extensions.Logging;
global using Uno.Extensions.DependencyInjection;


4 changes: 2 additions & 2 deletions src/Uno.Extensions.Navigation.UI/IRouteUpdater.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}

12 changes: 6 additions & 6 deletions src/Uno.Extensions.Navigation.UI/Navigator.cs
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ public class Navigator : INavigator, IInstance<IServiceProvider>

protected IRegion Region { get; }

private IRouteUpdater? RouteUpdater => Region.Services?.GetRequiredService<IRouteUpdater>();
private IRouteUpdater RouteUpdater => Region.Services!.GetRequiredService<IRouteUpdater>();

IServiceProvider? IInstance<IServiceProvider>.Instance => Region.Services;

Expand Down Expand Up @@ -42,7 +42,7 @@ protected Navigator(

public async Task<NavigationResponse?> NavigateAsync(NavigationRequest request)
{
var regionUpdateId = RouteUpdater?.StartNavigation(Region) ?? Guid.Empty;
RouteUpdater.StartNavigation(this, Region, request);
try
{

Expand All @@ -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}");

Expand Down Expand Up @@ -94,10 +97,7 @@ protected Navigator(
}
finally
{
if (RouteUpdater is { } routeUpdater)
{
await routeUpdater.EndNavigation(regionUpdateId);
}
RouteUpdater.EndNavigation(this, Region, request);
}
}

Expand Down
12 changes: 7 additions & 5 deletions src/Uno.Extensions.Navigation.UI/Regions/RegionExtensions.cs
Original file line number Diff line number Diff line change
Expand Up @@ -12,14 +12,16 @@ public static Task<bool> CanNavigate(this IRegion region, Route route)

public static Task<NavigationResponse?> NavigateAsync(this IRegion region, NavigationRequest request) => (region.Navigator()?.NavigateAsync(request)) ?? Task.FromResult<NavigationResponse?>(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;
}
/// <summary>
/// Returns the root region at the top of the region hierarchy
/// </summary>
/// <param name="region">The start point of the hierarchy search</param>
/// <returns>The root region</returns>
public static IRegion Root(this IRegion region) => region.Parent?.Root() ?? region;

internal static (Route?, IRegion, INavigator?)[] Ancestors(
this IRegion region,
Expand Down
57 changes: 28 additions & 29 deletions src/Uno.Extensions.Navigation.UI/RouteNotifier.cs
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
using System.Diagnostics;
using Uno.Extensions.Diagnostics;
using Uno.Extensions.Logging;

namespace Uno.Extensions.Navigation;
Expand All @@ -13,48 +14,46 @@ public RouteNotifier(ILogger<RouteNotifier> logger)
Logger = logger;
}

private IDictionary<Guid, IRegion> regionRoots= new Dictionary<Guid, IRegion>();
private IDictionary<IRegion, int> runningNavigations = new Dictionary<IRegion, int>();
private IDictionary<IRegion, Stopwatch> timers = new Dictionary<IRegion, Stopwatch>();
private IDictionary<Guid, StringBuilder> navigationSegments = new Dictionary<Guid, StringBuilder>();
private IDictionary<Guid, int> runningNavigations = new Dictionary<Guid, int>();

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()));
}
}
}
Expand Down
2 changes: 2 additions & 0 deletions src/Uno.Extensions.Navigation/NavigationRequest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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"}]";
Expand Down
8 changes: 8 additions & 0 deletions testing/TestHarness/Directory.Build.props
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,14 @@
<NoWarn>$(NoWarn);NU5104;NU1504;NU1505;CS1591;MSB3277;XA0101;CS8785;CS8669;CA1416</NoWarn>
<ManagePackageVersionsCentrally>true</ManagePackageVersionsCentrally>
<DisableImplicitLibraryPacksFolder>true</DisableImplicitLibraryPacksFolder>


<ConditionalCompilationSymbols>
<ConditionalCompilationSymbol Name="UNO_EXT_TIMERS" Comment="Controls whether performance timers are enabled (off by default)" />
</ConditionalCompilationSymbols>


<!--<DefineConstants>$(DefineConstants);UNO_EXT_TIMERS</DefineConstants>-->
</PropertyGroup>

<PropertyGroup>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
}

Expand Down
2 changes: 2 additions & 0 deletions testing/TestHarness/TestHarness.Shared/BaseTestSectionPage.cs
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@


using Uno.Extensions.Diagnostics;
using Uno.Toolkit.UI;

namespace TestHarness;
Expand All @@ -10,6 +11,7 @@ public partial class BaseTestSectionPage : Page, IDisposable

public BaseTestSectionPage()
{
PerformanceTimer.InitializeTimers();
Loaded += BaseTestSectionPage_Loaded;
}

Expand Down

0 comments on commit eabda02

Please sign in to comment.