In Blazor, is there any way to get render time for any component without its children?

Viewed 123

Because there seems to be no way to profile rendering slowness in Blazor, I've seen a need to get some kind of info about render timings.

In any Blazor component, I can get render time for any component like so:

private Stopwatch? RenderTimer { get; set; } = null;
protected override void OnInitialized() => RenderTimer = Stopwatch.StartNew();

protected override bool ShouldRender()
{
    RenderTimer = Stopwatch.StartNew(); // all re-renders (not the first render)
    return true;
}

protected override void OnAfterRender(bool firstRender)
{
    if (RenderTimer == null) return;
    RenderTimer.Stop();
    Console.WriteLine($"{(int)RenderTimer.ElapsedMilliseconds} ms to render {GetType().Name}");
}

But such a render time can include any or all of its subcomponents, because of course rendering a component might include rendering all its subcomponents.

Can you think of any way I can Stop the stopwatch before rendering each subcomponent and then start it again once back to rendering the content of this component-proper?

4 Answers

But such a render time includes all its subcomponents, because of course rendering a component includes rendering all its subcomponents.

It doesn't fit into the model in general to imagine that children always complete rendering before their parent. Steve Sanderson

In other words, a parent component can complete rendering herself before her children do... Depending on how you design and render your components.

However, generally speaking, you can achieve your objective the way you attempted to...

Here's a code sample with a parent and child component, which contains two event call backs that directs the parent component when to pause measuring its render time, and when to renew it (after the child component has been rendered), thus you can separate the render time of the parent component than that of the child component. From my observation, the render time of the child component is almost always the same, perhaps with a tiny variation.

Copy and test. Note: I'm using Blazor Server App without pre-rendering , .Net 5.0

WeatherForecastService.cs

using System.Threading;

public class WeatherForecastService
    {
        private static readonly string[] Summaries = new[]
        {
            "Freezing", "Bracing", "Chilly", "Cool", "Mild", "Warm", "Balmy", "Hot", "Sweltering", "Scorching"
        };

        public Task<WeatherForecast[]> GetForecastAsync(DateTime startDate)
        {
            Thread.Sleep(7000);
           
            // 2200 ms
            //int y = 100;

            //for (var x = 0; x < 1000000000; x++)
            //{
            //    y = y + 10;
            //}

            var rng = new Random();
            return Task.FromResult(Enumerable.Range(1, 5).Select(index => new WeatherForecast
            {
                Date = startDate.AddDays(index),
                TemperatureC = rng.Next(-20, 55),
                Summary = Summaries[rng.Next(Summaries.Length)]
            }).ToArray());
        }

        public WeatherForecast[] GetForecastAsync2(DateTime startDate)
        {
            Thread.Sleep(7000);

            // 2200 ms
            //int y = 100;

            //for (var x = 0; x < 1000000000; x++)
            //{
            //    y = y + 10;
            //}

            var rng = new Random();
            return Enumerable.Range(1, 5).Select(index => new WeatherForecast
            {
                Date = startDate.AddDays(index),
                TemperatureC = rng.Next(-20, 55),
                Summary = Summaries[rng.Next(Summaries.Length)]
            }).ToArray();
        }
    }

FetchData.razor

@page "/fetchdata"

@using RenderTime.Data
@using System.Diagnostics
@inject WeatherForecastService ForecastService

<h1>Weather forecast</h1>

<p>This component demonstrates fetching data from a service.</p>

@if (forecasts == null)
{
    <p><em>Loading...</em></p>
}
else
{
    <table class="table">
        <thead>
            <tr>
                <th>Date</th>
                <th>Temp. (C)</th>
                <th>Temp. (F)</th>
                <th>Summary</th>
            </tr>
        </thead>
        <tbody>
            @foreach (var forecast in forecasts)
            {
                <tr>
                    <td>@forecast.Date.ToShortDateString()</td>
                    <td>@forecast.TemperatureC</td>
                    <td>@forecast.TemperatureF</td>
                    <td>@forecast.Summary</td>
                </tr>
            }
        </tbody>
    </table>
}

@code {
    private WeatherForecast[] forecasts;

#nullable enable
    private Stopwatch? RenderTimer { get; set; } = null;
#nullable disable

    [Parameter]
    public EventCallback HandlerStart { get; set; }
    [Parameter]
    public EventCallback<int> HandlerEnd { get; set; }

    protected override async Task OnInitializedAsync()
    {
        RenderTimer = Stopwatch.StartNew();

        await HandlerStart.InvokeAsync();

        forecasts = await ForecastService.GetForecastAsync(DateTime.Now);
    }
    protected override async Task OnAfterRenderAsync(bool firstRender)
    {
        if (firstRender)
        {
            RenderTimer.Stop();
            var renderTime = (int)RenderTimer.ElapsedMilliseconds;

            await HandlerEnd.InvokeAsync(renderTime);
        }
    }
}

Parent.razor

@using System.Diagnostics

<FetchData HandlerStart="StopWatching" HandlerEnd="ProceedWatching" />

@code
{


#nullable enable
    private Stopwatch? RenderTimer { get; set; } = null;
#nullable disable

    private TimeSpan ts;
    protected override void OnInitialized()
    {
        RenderTimer = Stopwatch.StartNew();

    }

    private void StopWatching()
    {
        if (RenderTimer == null) return;

        RenderTimer.Stop();

        ts = RenderTimer.Elapsed;
        Console.WriteLine($"{ts.Milliseconds} before stop watching...");
    }

    private void ProceedWatching(int childComponentRendertime)
    {
        // if (RenderTimer == null) return;
        Console.WriteLine($"Child component render time: {childComponentRendertime}");

        RenderTimer.Start();
    }

    protected override void OnAfterRender(bool firstRender)
    {
        RenderTimer.Stop();
        Console.WriteLine($"{(int)RenderTimer.ElapsedMilliseconds} ms to render {GetType().Name}");
        
    }
}

Index.razor

@page "/"

<button @onclick="ToggleParent">@ToggleState</button>

@if(collapseParent)
  {
    @RenderParent()
  }

@code
{

    private bool collapseParent = false;
    private string ToggleState = "Show";


    private void ToggleParent()
    {
        collapseParent = !collapseParent;
        ToggleState =  collapseParent switch { true => "Hide", false => "Show"};

    }

    private RenderFragment RenderParent() => builder =>
    {
        builder.OpenComponent(0, typeof(Parent));

        builder.CloseComponent();

    };
}

There are two distinct processes going on in a component:

State Change

The following processes modify the component state:

  1. The lifecyle events - OnInitialized{Async}/OnParametersSet{Async}.

  2. UI Events registered in the component.

  3. Externally hooked up events.

  4. Direct calls by parent components to public methods.

ComponentBase manages the first two of these and requests one or more component renders by calling StateHasChanged.

You need to manually call StateHasChanged in the last two to request a component render.

Render

The call to StateHasChanged only places a RenderFragment on the Renderer's RenderQueue. It doesn't in itself cause a render. The renderer will run the render fragment when it gets thread time on the UI thread.

BlazorComponentBase

The component below is a black box equivalent version of ComponentBase with some timers and debug printing for the following:

  1. The OnInitialized{Async}/OnParametersSet{Async} lifecycle process.
  2. UI Events.
  3. The Render process run by the Renderer.

There are some important caveats to understand:

  1. Taking the measurements affects the timings.
  2. In any async process we're measuring the start to end time, not the actual execution time. Any yielding process may get "blocked" by another process and appear to take a long time.
using Microsoft.AspNetCore.Components.Rendering;
using Microsoft.AspNetCore.Components;
using System.Diagnostics;

public abstract class BlazorComponentBase : IComponent, IHandleEvent, IHandleAfterRender
{
    protected RenderFragment componentRenderFragment;
    private RenderHandle _renderHandle;
    protected bool initialized;
    protected bool hasNeverRendered = true;
    protected bool hasPendingQueuedRender;
    private bool _hasCalledOnAfterRender;

    protected virtual string ComponentName => this.GetType().Name;

    public BlazorComponentBase()
    {
        componentRenderFragment = builder =>
        {
            Debug.WriteLine($"{this.ComponentName} UI started a render at {GetTime()}");
            var timer = Stopwatch.StartNew();
            hasPendingQueuedRender = false;
            hasNeverRendered = false;
            BuildComponent(builder);
            Debug.WriteLine($"{this.ComponentName} rendered in {timer.Elapsed}");
        };
    }

    protected virtual void BuildComponent(RenderTreeBuilder builder)
        => BuildRenderTree(builder);

    protected virtual void BuildRenderTree(RenderTreeBuilder builder) { }

    protected virtual void OnInitialized() { }

    protected virtual Task OnInitializedAsync() => Task.CompletedTask;

    protected virtual void OnParametersSet() { }

    protected virtual Task OnParametersSetAsync() => Task.CompletedTask;

    protected void StateHasChanged()
        => _renderHandle.Dispatcher.InvokeAsync(Render);

    internal protected void Render()
    {
        if (hasPendingQueuedRender)
            return;

        if (hasNeverRendered || ShouldRender() || _renderHandle.IsRenderingOnMetadataUpdate)
        {
            hasPendingQueuedRender = true;

            try
            {
                _renderHandle.Render(componentRenderFragment);
            }
            catch
            {
                hasPendingQueuedRender = false;
                throw;
            }
        }
    }

    protected virtual bool ShouldRender() => true;

    protected virtual void OnAfterRender(bool firstRender) { }

    protected virtual Task OnAfterRenderAsync(bool firstRender) => Task.CompletedTask;

    protected Task InvokeAsync(Action workItem)
        => _renderHandle.Dispatcher.InvokeAsync(workItem);

    protected Task InvokeAsync(Func<Task> workItem)
        => _renderHandle.Dispatcher.InvokeAsync(workItem);

    void IComponent.Attach(RenderHandle renderHandle)
    {
        if (_renderHandle.IsInitialized)
            throw new InvalidOperationException($"The render handle is already set. Cannot initialize a {nameof(ComponentBase)} more than once.");

        _renderHandle = renderHandle;
    }

    public virtual async Task SetParametersAsync(ParameterView parameters)
    {
        Debug.WriteLine($"{this.ComponentName} UI started a lifecycle at {GetTime()}");
        var timer = Stopwatch.StartNew();
        parameters.SetParameterProperties(this);

        if (!initialized)
        {
            initialized = true;

            await this.RunInitAndSetParametersAsync();
        }
        else
            await this.CallOnParametersSetAsync();

        Debug.WriteLine($"{this.ComponentName} lifefcyled in {timer.Elapsed}");
    }

    private async Task RunInitAndSetParametersAsync()
    {
        this.OnInitialized();

        var task = this.OnInitializedAsync();

        if (task.Status != TaskStatus.RanToCompletion && task.Status != TaskStatus.Canceled)
        {
            this.Render();

            try
            {
                await task;
            }
            catch // avoiding exception filters for AOT runtime support
            {
                if (!task.IsCanceled)
                    throw;
            }
        }

        await this.CallOnParametersSetAsync();
    }

    private Task CallOnParametersSetAsync()
    {
        this.OnParametersSet();

        var task = this.OnParametersSetAsync();
        var shouldAwaitTask = task.Status != TaskStatus.RanToCompletion &&
            task.Status != TaskStatus.Canceled;

        Render();

        return shouldAwaitTask ?
            this.CallStateHasChangedOnAsyncCompletion(task) :
            Task.CompletedTask;
    }

    private async Task CallStateHasChangedOnAsyncCompletion(Task task)
    {
        try
        {
            await task;
        }
        catch
        {
            if (task.IsCanceled)
                return;

            throw;
        }
        Render();
    }

    async Task IHandleEvent.HandleEventAsync(EventCallbackWorkItem callback, object? arg)
    {
        Debug.WriteLine($"{this.ComponentName} UI started an event at {GetTime()}");
        var timer = Stopwatch.StartNew();

        var task = callback.InvokeAsync(arg);
        var shouldAwaitTask = task.Status != TaskStatus.RanToCompletion && task.Status != TaskStatus.Canceled;

        Render();

        if (shouldAwaitTask)
            await this.CallStateHasChangedOnAsyncCompletion(task);

        Debug.WriteLine($"{this.ComponentName} UI evented in {timer.Elapsed}");
    }

    Task IHandleAfterRender.OnAfterRenderAsync()
    {
        var firstRender = !_hasCalledOnAfterRender;
        _hasCalledOnAfterRender |= true;

        OnAfterRender(firstRender);

        return this.OnAfterRenderAsync(firstRender);
    }

    private string GetTime()
    {
        Math.DivRem(DateTime.Now.Ticks, TimeSpan.TicksPerMillisecond, out long millisecondparts);
        var mills = DateTime.Now.Ticks / TimeSpan.TicksPerMillisecond;
        Math.DivRem(mills, 1000, out long millseconds);
        return $" {DateTime.Now.ToLongTimeString()}:{millseconds}:{millisecondparts}";
    }
}

Here's a set of results from the standard Blazor template.

// F5 on Index
App UI started a lifecycle at  16:10:19:465:2698
App UI started a render at  16:10:19:468:3597
App rendered in 00:00:00.0001903
NavMenu UI started a lifecycle at  16:10:19:475:9989
NavMenu lifefcyled in 00:00:00.0000164
Index UI started a lifecycle at  16:10:19:480:766
Index lifefcyled in 00:00:00.0000205
NavMenu UI started a render at  16:10:19:486:1515
NavMenu rendered in 00:00:00.0000303
Index UI started a render at  16:10:19:491:4845
Index rendered in 00:00:00.0000197
SurveyPrompt UI started a lifecycle at  16:10:19:498:1386
SurveyPrompt lifefcyled in 00:00:00.0000244
SurveyPrompt UI started a render at  16:10:19:503:8187
SurveyPrompt rendered in 00:00:00.0000147
App lifefcyled in 00:00:00.0420088
...
//changed to the FetchData page
NavMenu UI started an event at  16:11:08:611:4731
NavMenu UI evented in 00:00:00.0003278
NavMenu UI started a render at  16:11:08:617:61
NavMenu rendered in 00:00:00.0000705
FetchData UI started a lifecycle at  16:11:08:633:7379
FetchData lifefcyled in 00:00:00.0031458
FetchData UI started a render at  16:11:08:641:7874
FetchData rendered in 00:00:00.0010507
....
// Changed to the Counter page
NavMenu UI started an event at  16:11:10:612:2966
NavMenu UI evented in 00:00:00.0000210
NavMenu UI started a render at  16:11:10:616:7572
NavMenu rendered in 00:00:00.0000292
Counter UI started a lifecycle at  16:11:10:622:4540
Counter lifefcyled in 00:00:00.0002307
Counter UI started a render at  16:11:10:628:9948
Counter rendered in 00:00:00.0008271
.....
// Clicked the increment button
Counter UI started an event at  16:11:12:53:9117
Counter UI evented in 00:00:00.0003249
Counter UI started a render at  16:11:12:66:2064
Counter rendered in 00:00:00.0000431

It depends on you definition of 'Rendering'.

If I take that to be the running of the markup (RenderTreeBuilder) code it becomes really simple:

@page "/counter"
@using System.Diagnostics
@using System.Runtime.CompilerServices

@{
    Report("Render Start");
}

<PageTitle>Counter</PageTitle>

<h1>Counter</h1>

  ... some test content omitted 

@{
    Report("Render Finish");
}

@code {   

  protected override bool ShouldRender()
  {
     renderTimer.Restart();
     Report();
     return base.ShouldRender();
  }
  
  ...

}

You can put some diagnostic WriteLines in a few SubComponents to verify that they all run after Report("Render Finish");. Typical output, with a 100ms delay in the subcomponents:

00:00:00.0000052 Counter ShouldRender
00:00:00.0001773 Counter Render Start
00:00:00.0002560 Counter Render Finish
SubComp 0 ShouldRender
SubComp 1 ShouldRender
SubComp 2 ShouldRender
SubComp 0 BuildRenderTree
SubComp 1 BuildRenderTree
SubComp 2 BuildRenderTree
00:00:00.3205424 Counter OnAfterRender
SubComp 0 OnAfterRender
SubComp 1 OnAfterRender
SubComp 2 OnAfterRender

As you can see, in OnAfterRender() of the main component you measure most of the childcomponents code.

This answer is intended to be controversial as this is an immensely complex topic.

Most of the code in most components is never run, and most of the renders that occur due to Ui events result in no UI updates.

The world doesn't begin and end with ComponentBase, though it may be a little hard to believe.

public class RadzenComponent : ComponentBase, IDisposable
public abstract class MudComponentBase : ComponentBase

Most of the developer-facing component lifecycle concepts are encapsulated in this base class. The core components rendering system doesn't know about them (it only knows about IComponent). This gives us flexibility to change the lifecycle concepts easily, or for developers to design their own lifecycles as different base classes.

This is the comment at the top of the ComponentBase code. I don't think MS ever dreamed ComponentBase would become another Google!

Consider this implementation:

using Microsoft.AspNetCore.Components.Rendering;
using Microsoft.AspNetCore.Components;

namespace Blazr.Components;
public abstract class LeanComponentBase : IComponent
{
    protected RenderFragment renderFragment;
    private RenderHandle _renderHandle;
    protected bool initialized;
    private bool _hasNeverRendered = true;
    private bool _hasPendingQueuedRender;

    [Parameter] public Boolean Hidden { get; set; } = false;

    public LeanComponentBase()
    {
        this.renderFragment = builder =>
        {
            if (!this.Hidden)
            {
                _hasPendingQueuedRender = false;
                _hasNeverRendered = false;
                this.BuildRenderTree(builder);
            }
        };
    }

    void IComponent.Attach(RenderHandle renderHandle)
        => _renderHandle = renderHandle;

    public virtual async Task SetParametersAsync(ParameterView parameters)
    {
        parameters.SetParameterProperties(this);
        var shouldRender = this.ShouldRenderOnParameterChange(initialized);

        if (_hasNeverRendered || shouldRender)
        {
            await this.OnParameterChangeAsync(!initialized);
            this.Render();
        }

        this.initialized = true;
    }

    protected virtual void BuildRenderTree(RenderTreeBuilder builder) { }

    protected virtual ValueTask OnParameterChangeAsync(bool firstRender)
        => ValueTask.CompletedTask;

    protected virtual bool ShouldRenderOnParameterChange(bool initialized)
        => true;

    protected void Render()
    {
        if (_hasPendingQueuedRender)
            return;

        _hasPendingQueuedRender = true;
        _renderHandle.Render(renderFragment);
    }

    protected void StateHasChanged()
        => _renderHandle.Dispatcher.InvokeAsync(Render);
}

You:

  1. Can take control of whether a parameter update caused a render cascade.
  2. You control rendering on UI events.
  3. There's one lifecycle event.
Related