diff --git a/ClimateExplorer.Web.Client/Components/Chart/ChartView.razor.cs b/ClimateExplorer.Web.Client/Components/Chart/ChartView.razor.cs index 8bef2aa30..922930d0e 100644 --- a/ClimateExplorer.Web.Client/Components/Chart/ChartView.razor.cs +++ b/ClimateExplorer.Web.Client/Components/Chart/ChartView.razor.cs @@ -10,6 +10,7 @@ namespace ClimateExplorer.Web.Client.Components.Chart; using ClimateExplorer.Core.Model; using ClimateExplorer.Core.ViewModel; using ClimateExplorer.Web.Client.Components.Common; +using ClimateExplorer.Web.Client.Infrastructure; using ClimateExplorer.Web.Client.UiModel; using ClimateExplorer.Web.UiLogic; using ClimateExplorer.Web.UiModel; @@ -346,6 +347,8 @@ protected override async Task OnAfterRenderAsync(bool firstRender) protected async Task BuildDataSets() { + using var perf = PerformanceLogScope.Start(Logger!, "ChartView.BuildDataSets", ("pageName", PageName), ("locationId", LocationId), ("seriesCount", ChartSeriesList?.Count ?? 0)); + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.mark", "chart-build-start", new { pageName = PageName, locationId = LocationId, seriesCount = ChartSeriesList?.Count ?? 0 }); // This method is called whenever anything has occurred that may require the chart to // be re-rendered. // @@ -432,16 +435,23 @@ protected async Task BuildDataSets() l.LogInformation("Set ChartSeriesWithData after call to RetrieveDataSets(). ChartSeriesWithData now has " + usableChartSeries.Count() + " entries."); + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.mark", "chart-data-loaded", new { pageName = PageName, locationId = LocationId, seriesCount = ChartSeriesWithData?.Count ?? 0, recordCount = ChartSeriesWithData?.Sum(x => x.SourceDataSet?.DataRecords?.Count ?? 0) ?? 0 }); + // Render the series await RenderChart(); buildDataSetsInProcess = false; + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.mark", "chart-render-complete", new { pageName = PageName, locationId = LocationId, seriesCount = ChartSeriesWithData?.Count ?? 0 }); + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.measure", "chart-data-load", "chart-build-start", "chart-data-loaded", new { pageName = PageName, locationId = LocationId }); + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.measure", "chart-build-to-render", "chart-build-start", "chart-render-complete", new { pageName = PageName, locationId = LocationId }); + l.LogInformation("Leaving"); } protected async Task RenderChart() { + using var perf = PerformanceLogScope.Start(Logger!, "ChartView.RenderChart", ("pageName", PageName), ("locationId", LocationId), ("seriesCount", ChartSeriesWithData?.Count ?? 0)); var l = new LogAugmenter(Logger!, "RenderChart"); l.LogInformation("Entering"); diff --git a/ClimateExplorer.Web.Client/Components/Location/LocationDashboard.razor.cs b/ClimateExplorer.Web.Client/Components/Location/LocationDashboard.razor.cs index 3644e7302..5fdaffd3e 100644 --- a/ClimateExplorer.Web.Client/Components/Location/LocationDashboard.razor.cs +++ b/ClimateExplorer.Web.Client/Components/Location/LocationDashboard.razor.cs @@ -7,6 +7,7 @@ namespace ClimateExplorer.Web.Client.Components.Location; using ClimateExplorer.Core.ViewModel; using ClimateExplorer.Web.Client.Components.Common; using ClimateExplorer.Web.Client.Components.Info; +using ClimateExplorer.Web.Client.Infrastructure; using ClimateExplorer.Web.Client.Services; using ClimateExplorer.Web.Client.UiModel; using ClimateExplorer.Web.UiModel; @@ -109,6 +110,7 @@ protected override void OnInitialized() protected override async Task OnParametersSetAsync() { + using var perf = PerformanceLogScope.Start(Logger!, "LocationDashboard.OnParametersSetAsync", ("locationId", Location?.Id), ("locationName", Location?.Name)); if (Location == null || DataSetDefinitions == null) { RecentObservationsSupported = false; @@ -140,6 +142,7 @@ protected override async Task OnParametersSetAsync() protected override async Task OnAfterRenderAsync(bool firstRender) { + using var perf = PerformanceLogScope.Start(Logger!, "LocationDashboard.OnAfterRenderAsync", ("firstRender", firstRender), ("locationId", Location?.Id), ("loadStripeData", LoadStripeData)); if (Location == null || DataSetDefinitions == null) { return; @@ -151,6 +154,8 @@ protected override async Task OnAfterRenderAsync(bool firstRender) Logger!.LogInformation("Loading data"); + await JS!.InvokeVoidAsync("climateExplorerPerformance.mark", "location-dashboard-data-start", new { locationId = Location?.Id, locationName = Location?.Name }); + var temperatureAnomaly = await CalculateAnomaly(DataSubstitute.StandardTemperatureDataMatches(), ContainerAggregationFunctions.Mean); if (temperatureAnomaly != null) { @@ -192,6 +197,9 @@ protected override async Task OnAfterRenderAsync(bool firstRender) var recentObservationsSupport = await DataService!.GetRecentObservations(Location!.Id, DataType.TempMax, isLocationSupported: true); RecentObservationsSupported = recentObservationsSupport.IsSupported; + await JS!.InvokeVoidAsync("climateExplorerPerformance.mark", "location-dashboard-data-loaded", new { locationId = Location?.Id, hasTemperatureAnomaly = temperatureAnomaly != null, recentObservationsSupported = RecentObservationsSupported }); + await JS!.InvokeVoidAsync("climateExplorerPerformance.measure", "location-dashboard-data", "location-dashboard-data-start", "location-dashboard-data-loaded", new { locationId = Location?.Id }); + StripeLoadingIndicatorVisible = false; StateHasChanged(); diff --git a/ClimateExplorer.Web.Client/Infrastructure/PerformanceLogScope.cs b/ClimateExplorer.Web.Client/Infrastructure/PerformanceLogScope.cs new file mode 100644 index 000000000..4faebc415 --- /dev/null +++ b/ClimateExplorer.Web.Client/Infrastructure/PerformanceLogScope.cs @@ -0,0 +1,39 @@ +namespace ClimateExplorer.Web.Client.Infrastructure; + +using System.Diagnostics; + +public sealed class PerformanceLogScope : IDisposable +{ + private readonly ILogger logger; + private readonly string name; + private readonly IReadOnlyDictionary context; + private readonly long startTimestamp; + private bool disposed; + + private PerformanceLogScope(ILogger logger, string name, IReadOnlyDictionary context) + { + this.logger = logger; + this.name = name; + this.context = context; + startTimestamp = Stopwatch.GetTimestamp(); + + logger.LogInformation("PerfStart {Name} {@Context}", name, context); + } + + public static PerformanceLogScope Start(ILogger logger, string name, params (string Key, object? Value)[] context) + { + return new PerformanceLogScope(logger, name, context.ToDictionary(x => x.Key, x => x.Value)); + } + + public void Dispose() + { + if (disposed) + { + return; + } + + disposed = true; + var elapsedMilliseconds = Stopwatch.GetElapsedTime(startTimestamp).TotalMilliseconds; + logger.LogInformation("PerfEnd {Name} elapsedMs={ElapsedMilliseconds:0.0} {@Context}", name, elapsedMilliseconds, context); + } +} diff --git a/ClimateExplorer.Web.Client/Pages/Index.razor.cs b/ClimateExplorer.Web.Client/Pages/Index.razor.cs index 04455fd34..9f8d7e96a 100644 --- a/ClimateExplorer.Web.Client/Pages/Index.razor.cs +++ b/ClimateExplorer.Web.Client/Pages/Index.razor.cs @@ -4,6 +4,7 @@ namespace ClimateExplorer.Web.Client.Pages; using ClimateExplorer.Core.ViewModel; using ClimateExplorer.Web.Client.Components.Common; using ClimateExplorer.Web.Client.Components.Location; +using ClimateExplorer.Web.Client.Infrastructure; using ClimateExplorer.Web.Client.Services; using Microsoft.AspNetCore.Components; using Microsoft.AspNetCore.WebUtilities; @@ -73,6 +74,8 @@ public override void Dispose() protected override async Task OnInitializedAsync() { + using var perf = PerformanceLogScope.Start(Logger!, "Index.OnInitializedAsync", ("locationString", LocationString)); + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.mark", "index-initialized-start", new { locationString = LocationString }); // Check to see if a named location is being requested. That will look like /location/ Location = await GetLocationFromPath(); @@ -105,6 +108,8 @@ protected override async Task OnParametersSetAsync() protected override async Task OnAfterRenderAsync(bool firstRender) { + using var perf = PerformanceLogScope.Start(Logger!, "Index.OnAfterRenderAsync", ("firstRender", firstRender), ("hasDataSetDefinitions", DataSetDefinitions is not null), ("locationId", Location?.Id)); + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.mark", firstRender ? "index-first-render-start" : "index-render-start", new { locationId = Location?.Id, hasDataSetDefinitions = DataSetDefinitions is not null }); if (firstRender) { SiteOverviewService!.ShowRequested += HandleShowRequested; @@ -116,7 +121,10 @@ protected override async Task OnAfterRenderAsync(bool firstRender) var locationsTask = DataService!.GetLocations(false); var regionsTask = DataService!.GetRegions(); - await Task.WhenAll(dataSetDefinitionsTask, locationsTask, regionsTask); + using (PerformanceLogScope.Start(Logger!, "Index.LoadReferenceData")) + { + await Task.WhenAll(dataSetDefinitionsTask, locationsTask, regionsTask); + } DataSetDefinitions = [.. await dataSetDefinitionsTask]; LocationDictionary = (await locationsTask).ToDictionary(x => x.Id, x => x); @@ -155,6 +163,9 @@ protected override async Task OnAfterRenderAsync(bool firstRender) } } + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.mark", "index-reference-data-loaded", new { locationCount = LocationDictionary?.Count, dataSetDefinitionCount = DataSetDefinitions?.Count(), regionCount = Regions?.Count() }); + await JsRuntime!.InvokeVoidAsync("climateExplorerPerformance.measure", "index-reference-data", "index-first-render-start", "index-reference-data-loaded", new { locationId = Location?.Id }); + StateHasChanged(); } diff --git a/ClimateExplorer.Web/App.razor b/ClimateExplorer.Web/App.razor index 149776a08..40f6831e5 100644 --- a/ClimateExplorer.Web/App.razor +++ b/ClimateExplorer.Web/App.razor @@ -83,6 +83,7 @@ the chart to silently fail to initialise and remain stuck on the loading spinner. Execution order of the two chart scripts is preserved because they are sequential. --> +