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

Question

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?

Answer 1

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