Blazor Performance Diagnostics for Re-Rendering and Execution times.

[MichaelPeter]

The Problem:

Blazor Performance problems often arise becaues of too frequent and unintended Re-Renders:

For example:

• Unexpected Parameters changes: A objekt-parameter is recreated in the render loop and causes rerenders because it is a parameter change. (No-nos like passing lambdas as parameters)
• One Child Component for some reason is rerendered 10 times on changes.
• Some component maybe throws unintended events which caues rerenders.
• A costly operation (Rest call) is executed while wating for the task to complete multiple renders happen.
• A REST Call is made in OnParametersSet() or OnAfterRender() and by error this rest call is executed multiple times since unexpected Rerenders.

With one Component this can be debugged with console messages in OnParametersSet() or OnAfterRender, but in case of a complex render three with different components this gets quite compilcated to diagnose Performance Bottlenecks.

Also it is often difficult to see which changes cause rerenders in child components. Or which await calls for for responses from Webservices also cause rerenders between initiating the call and completing the call.

Potential Solution:

Some possiblily / Component / API, which allows globally to trace all OnSetParameters, Renders etc. with execution times, to see if renders happen too frequent, how long it is executed and what caues the bottlenecks.

at first maybe an API to hook into the render events of all components would be maybe already enough. Otherwise I would need make a custom ComponentBase class which traces all Steps like BuildRenderTree() or OnAfterRender().

Example

A example output log

Navigation.Component1 InitalizeAsync() took 100 Milliseconds
Navigation.Component1 Inital Render:
Navigation.Component1 BuildRenderTree() took 10 milliseconds
Navigation.Component1.SubComponent Initalize() took 400 milliseconds
Navigation.Component1 Inital Render:
Navigation.Component1 Render because parameter change.
Navigation.Component1.SubComponent BuildRenderTree() took 10 milliseconds
Navigation.Component1 Render because parameter change.
Navigation.Component1.SubComponent BuildRenderTree() took 10 milliseconds
Navigation.Component1 Render because parameter change.
Navigation.Component1.SubComponent BuildRenderTree() took 10 milliseconds
Navigation.Component1 Render because eventhanlder onclick
Navigation.Component1.SubComponent BuildRenderTree() took 10 milliseconds

A integration into the Performance Monitor is maybe possible in Blazor Server Side but on the Blazor Webassembly side only general Browser tools for Webassembly would be possible. Of which I am not aware of yet.

[ghost]

We've moved this issue to the Backlog milestone. This means that it is not going to be worked on for the coming release. We will reassess the backlog following the current release and consider this item at that time. To learn more about our issue management process and to have better expectation regarding different types of issues you can read our Triage Process.

[pranavkm]

Have you looked at the Debug logs Blazor currently includes? The component lifecycle methods aren't as fine-grained as you mention here, but you can glean a some of the details that you included here.

[MichaelPeter]

Hello @pranavkm,

thank you for your reply, this is actually helpfull and a first step.

builder.Logging.SetMinimumLevel(LogLevel.Trace);

But it just tells me what has been rerendered, not how long the rendering took, or how long it took or what steps took how long. I only could write a custom logger which measures the time between the render log messages to get some feeling of time, but this is really hacky, time consuming and not really sufficent.

      Rendering component 1042 of type VeriCore.Client.Shared.Validation.FormFieldValidationMessage
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1044 of type VeriCore.Client.Shared.Validation.FormFieldValidationMessage
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1046 of type VeriCore.Client.Shared.Validation.FormFieldValidationMessage
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1048 of type VeriCore.Client.Shared.Validation.FormFieldValidationMessage
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1050 of type VeriCore.Client.Shared.Validation.FormFieldValidationMessage
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1041 of type DevExpress.Blazor.DxTextBox
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1043 of type DevExpress.Blazor.DxTextBox
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1045 of type DevExpress.Blazor.DxTextBox
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]
      Rendering component 1047 of type DevExpress.Blazor.DxTextBox
dbug: Microsoft.AspNetCore.Components.RenderTree.Renderer[3]

I mean maybe I check the

[pranavkm]

There's a way to get console loggers to include timestamps: https://docs.microsoft.com/dotnet/core/extensions/console-log-formatter#set-formatter-with-configuration. One thing to note is that the logging does not include the end times, so you kinda have to reverse engineer it (look at when the sibling component is rendered or the renderbatch is sent). We might be open to accepting a PR that adds that adds an additional log statement here that would log at the end of a component render: https://github.com/dotnet/aspnetcore/blob/main/src/Components/Components/src/RenderTree/Renderer.cs#L790-L791.

FYI @SteveSandersonMS since this code-path is perf sensitive.

[MichaelPeter]

Thank you @pranavkm for the offer of a PR,

hope you could enjoy the hollidays

sorry for just writing now, but needed to first understand a bit the render code of blazor. The position you suggested is nice but doesn't help much since mostly the BuildRenderTree() itself is not the performance problem since they don't even allow async operations.

The problem are Initialize(Async) and AfterRender(Async) and the rarely used SetParameters(Async) in case I want to retrieve data before rendering.

I forked aspnetcore and made a small commit, this is just an Idea and a basis for discussion without tests and checks if it even compiles, definitly not final code. And guess you wouldn't accept this pull anyway. https://github.com/MichaelPeter/aspnetcore/commit/ebbc82b0a7c869e0d156f8391de1e2531bdf62e2

Edit: Now the latest changes are in this branch: https://github.com/MichaelPeter/aspnetcore/commits/michaelpeter/performancelogging

Now the following logs happen:

1. HandleEvent - now with the component id to be able to associate the event execution time to a component
2. Initializing and Setting Parameters - or just SettingParameters. The SettingParameters maybe results in log spam, but allows to find out how long an eventuell event handler before took.
3. The old RenderingComponent to know how long Initialize(Async) and SetParameters(Async) took
4. RenderedComponent - Can also be ommited but allows a more complete picture, if in rare cases my BuildRenderTree code is slow.
5. AfterRender(Async) completed, allows me to know with RenderedComponent how long the after render took
6. The old component disposed log stays unchanged.

The Idea is then releasing a nuget package, which I can start in development enviroments with .UsePerformanceVisualizer(), this tracks logs of components (maybe with press of a keyboard shortcut) and after stopping protcolling I can visualize it with something like https://github.com/jlfwong/speedscope edge://tracing/ or console.profile/console.profileEnd()

https://user-images.githubusercontent.com/150329/40900669-86eced80-6781-11e8-92c1-dc667b651e72.gif

I think the most complaints about blazor performance (especially from beginners or during evalution) come from not understanding the blazor lifecycle. Or building some code which causes massive rerenders. Also tried the DevExpress components and their Performance is just abysmal and would like to understand if we just use them wrong or the components themselfs are quite flawed.

[pranavkm]

Those look like reasonable changes. If you happen to have the time, could you try doing a before / after of our benchmarks: https://github.com/dotnet/aspnetcore/tree/main/src/Components/benchmarkapps/Wasm.Performance? Logging typically has no impact when disabled, but this would alleviate any concerns of perf impact.

[SteveSandersonMS]

Logging typically has no impact when disabled, but this would alleviate any concerns of perf impact.

This certainly might turn out to be the case, but I agree about comparing the benchmarks. The perf characteristics of the Mono interpreter can be quite different from CoreCLR with JIT. Lots of small changes (e.g., passing one extra arg to a method in a hot loop) can add up to a measurable difference.

[szalapski]

(FYI #40867 is related)

I've written an article on the problem of thousands of unnecessary re-renderings and one on my solution (to avoid repetitive yet custom ShouldRender overrides), but it isn't a perfect approach for sure. Still, it's better than nothing, and maybe it will help inspire something? I have two other ideas that might help, but I am stuck on how I might implement either given that it might involve the guts of how components work. Would anyone want to talk these ideas over?

[ghost]

Thanks for contacting us.

We're moving this issue to the .NET 8 Planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s). If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[ghost]

We've moved this issue to the Backlog milestone. This means that it is not going to be worked on for the coming release. We will reassess the backlog following the current release and consider this item at that time. To learn more about our issue management process and to have better expectation regarding different types of issues you can read our Triage Process.

[ghost]

Thanks for contacting us.

We're moving this issue to the .NET 9 Planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s). If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues. To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.

[Hona]

This would be quite valuable to diagnose and find problem components that:

• rerender a single instance a lot
• take a long time to render once
• has many instances across the app rendering

To help performance tune :)