Blazor Wasm performance regression

[lewing]

The blazor wasm benchmarks are showing a regression in the range

c3fa2bb...e93c889

There is no comparable regression showing from the https://github.com/dotnet/perf-autofiling-issues/issues?q=is%3Aopen+is%3Aissue+label%3Aarch-wasm or https://radekdoulik.github.io/WasmPerformanceMeasurements/ nor does the commit range include runtime/sdk updates so the regression is likely in aspnetcore.

The benchmark app is https://github.com/dotnet/aspnetcore/tree/828955caf1442ea13383fe0d2a75d388b8c54215/src/Components/benchmarkapps/Wasm.Performance

[lewing]

it would be a good idea to make sure there wasn't a change in the host environment for the benchmark either (e.g. chrome version change)

[javiercn]

I looked at Comparing c3fa2bb74917b3b191623fe9202f26e952f9c7ba...e93c8894d08cc46c275dbda902d485dfeb690783 · dotnet/aspnetcore

Looking at the range, I can't really see any place where this could be an issue other than [Blazor] Add IPersistentComponentStateSerializer interface for cus… · dotnet/aspnetcore@8883b98 but that was fixed already https://github.com/dotnet/aspnetcore/blob/main/src/Components/Components/src/PersistentState/PersistentValueProviderComponentSubscription.cs#L19

The app is a standalone webassembly app that doesn't use any of the persistent state features (afaik) there won't even be persistent state coming in from a server because there isn't any

We can look and see if something else in the infrastructure has changed that might be skewing the numbers

[pavelsavara]

TL;DR - something is different but I'm not sure why.

This is the new event-pipe profiler and PerfView diff.
The workload is startup+rendering 100 divs about 10K times with different text (Int32.ToString).

Base is 10.0.0-preview.6.25358.103 of Microsoft.AspNetCore.Components.WebAssembly
Test is 10.0.0-rc.1.25407.1 of Microsoft.AspNetCore.Components.WebAssembly
Both build with 10.0.100-preview.6.25358.103/10.0.100 wasm-tools and 10.0.100-preview.7.25322.101 SDK.
Both published/release/dissabled debugger/Timing-Allow-Origin
Both chrome 138.0.7204.184 (Official Build) (64-bit)
Both on windows dev box.
Both exhibit jiterp optimizations.

Scroll right for numbers.

Module	Base	Test	Delta	Responsibility %	Overweight %	Interest Level
<<System.Int32.ToString()>>	10622.8	15418.0	4795.2	177.80	2636.99	6
<<Rendering.RenderTreeBuilder.AddContent(int,object)>>	16458.8	23857.0	7398.2	274.31	2625.82	6
Client <<Client!Client.Pages.Home.BuildRenderTree(Rendering.RenderTreeBuilder)>>	35899.7	50791.8	14892.1	552.18	2423.28	6
System.Collections <<System.Collections!Stack<System.Int32>.Push(int)>>	1886.0	2757.5	871.5	32.31	2699.39	5
<<Rendering.RenderTreeBuilder.AddContent(int,string)>>	3845.9	5622.1	1776.2	65.86	2697.93	5
<<Rendering.RenderTreeBuilder.OpenElement(int,string)>>	5907.8	8313.8	2406.0	89.21	2379.07	5
<<Rendering.RenderTreeBuilder.AddMarkupContent(int,string)>>	3867.8	5246.7	1378.9	51.13	2082.60	5
<<Rendering.RenderTreeBuilder.CloseElement()>>	4077.2	5231.0	1153.8	42.78	1653.12	5
System.Collections <<System.Collections!Stack<System.Int32>.Pop()>>	2053.4	2627.7	574.3	21.29	1633.82	5
<<System.Threading.ThreadPool.BackgroundJobHandler()>>	120758.1	125307.0	4548.9	168.67	220.05	5
<<System.Threading.ThreadPoolWorkQueue.Dispatch()>>	31544.1	30103.1	-1440.9	-53.43	-266.85	5
<>	36678.9	34842.8	-1836.1	-68.08	-292.43	5
<<System.MulticastDelegate.Equals(object)>>	11.8	147.5	135.7	5.03	67179.43	4
Web <<Web!Web.PageTitle.BuildRenderTree(Rendering.RenderTreeBuilder)>>	38.3	267.6	229.3	8.50	34973.87	4
<<Rendering.RenderTreeBuilder.OpenComponentUnchecked(int,System.Type)>>	47.1	251.0	203.9	7.56	25289.18	4
System.Collections.Concurrent <<ConcurrentDictionary<System.Type,System.Boolean>.GetOrAdd(System.Type,System.Func`2<System.Type, bool>)>>	43.5	187.3	143.8	5.33	19311.15	4
Web <<Web!Web.PageTitle.BuildTitleRenderTree(Rendering.RenderTreeBuilder)>>	92.3	258.4	166.1	6.16	10512.51	4
<<System.Array.Copy(System.Array,System.Array,int)>>	277.7	465.7	188.0	6.97	3954.76	4
<<System.Array.Clear(System.Array,int,int)>>	298.9	497.6	198.7	7.37	3883.39	4
WebAssembly <<WebAssemblyRenderer.ProcessPendingRender()>>	150587.7	153742.6	3154.9	116.98	122.39	4
Client <<Client!Client.Pages.Home.d__4.MoveNext()>>	153720.2	156705.8	2985.6	110.70	113.46	4
<<ComponentBase.StateHasChanged()>>	153741.0	156689.8	2948.8	109.34	112.05	4
WebAssembly <<WebAssemblyCallQueue.Schedule(WebAssemblyRenderer,System.Action`1)>>	3099.0	2862.3	-236.7	-8.78	-446.18	4
WebAssembly <<WebAssemblyRenderer.CallBaseProcessPendingRender()>>	6378.2	5872.7	-505.5	-18.74	-462.98	4
Client <<Client!Client.Pages.Home.IncrementCount()>>	3251.8	2982.3	-269.5	-9.99	-484.14	4
<<RenderTree.RenderTreeDiffBuilder.AppendDiffEntriesForRange(RenderTree.RenderTreeDiffBuilder/DiffContext&,int,int,int,int)>>	1423.3	1244.9	-178.4	-6.61	-732.21	4
WebAssembly <<InternalJSImportMethods.d__3.MoveNext()>>	310.8	162.6	-148.2	-5.50	-2785.52	4
<<AsyncTaskMethodBuilder.AsyncStateMachineBox<RootComponentOperationBatch,InternalJSImportMethods.d__3>.ExecuteFromThreadPool(System.Threading.Thread)>>	310.8	162.6	-148.2	-5.50	-2785.52	4
<<AsyncTaskMethodBuilder.AsyncStateMachineBox<RootComponentOperationBatch,InternalJSImportMethods.d__3>.ExecutionContextCallback(object)>>	310.8	162.6	-148.2	-5.50	-2785.52	4
<<Dictionary<System.Object,Rendering.KeyedItemInfo>.Clear()>>	16.5	136.4	119.9	4.45	42449.61	3
<<Dictionary<System.Object,List<Sections.SectionContent>>.TryGetValue(object,List`1<Sections.SectionContent>&)>>	10.7	83.0	72.3	2.68	39472.35	3
<<System.Buffers.SharedArrayPool<RenderTree.RenderTreeFrame>.Rent(int)>>	27.0	148.4	121.4	4.50	26265.97	3
<<Dictionary<System.Object,Rendering.KeyedItemInfo>.TryGetValue(object,Rendering.KeyedItemInfo&)>>	38.0	168.6	130.6	4.84	20076.96	3
<<Rendering.RenderTreeBuilder.AddContent(int,RenderFragment)>>	27.0	104.9	77.9	2.89	16854.36	3
<<Dictionary<System.Object,Rendering.KeyedItemInfo>.FindValue(object)>>	31.9	108.3	76.4	2.83	13990.75	3
<<Dictionary<System.Object,Rendering.KeyedItemInfo>.TryInsert(object,Rendering.KeyedItemInfo,InsertionBehavior)>>	75.9	142.1	66.2	2.45	5095.12	3
Microsoft.JSInterop <<Microsoft.JSInterop!Microsoft.JSInterop.Infrastructure.DotNetDispatcher.EndInvokeJS(Microsoft.JSInterop.JSRuntime,string)>>	202.3	323.9	121.6	4.51	3511.37	3
WebAssembly <<DefaultWebAssemblyJSRuntime.__Wrapper_EndInvokeJS_92020726(JSMarshalerArgument*)>>	211.5	325.7	114.2	4.23	3154.24	3
<<RenderTree.Renderer.ProcessRenderQueue()>>	155587.6	158334.0	2746.4	101.83	103.12	3
Threads	157549.7	160247.6	2697.9	100.03	100.03	3
ROOT	157549.7	160247.6	2697.9	100.03	100.03	3
(Non-Activities)	157549.7	160247.6	2697.9	100.03	100.03	3
Thread (1)	157549.7	160247.6	2697.9	100.03	100.03	3
<<RenderHandle.Render(RenderFragment)>>	1584.4	1473.7	-110.7	-4.10	-408.15	3
WebAssembly <<WebAssemblyHost.d__15.MoveNext()>>	274.4	151.2	-123.2	-4.57	-2622.80	3
<<AsyncTaskMethodBuilder.Start(RenderTree.Renderer/d__68&)>>	242.6	118.6	-124.0	-4.60	-2985.86	3
<<RenderTree.Renderer.d__68.MoveNext()>>	242.6	118.6	-124.0	-4.60	-2985.86	3
<<RenderTree.Renderer.RenderRootComponentAsync(int,ParameterView)>>	242.6	118.6	-124.0	-4.60	-2985.86	3
<<ComponentBase.d__28.MoveNext()>>	242.6	115.5	-127.1	-4.71	-3060.51	3
<<AsyncTaskMethodBuilder.Start(ComponentBase/d__28&)>>	242.6	115.5	-127.1	-4.71	-3060.51	3
<<ComponentBase.RunInitAndSetParametersAsync()>>	242.6	115.5	-127.1	-4.71	-3060.51	3
WebAssembly <<WebAssemblyHost.<>c__DisplayClass15_1.<b__1>d.MoveNext()>>	252.6	118.6	-134.0	-4.97	-3098.92	3
<<AsyncVoidMethodBuilder.Start(WebAssemblyHost/<>c__DisplayClass15_1/<b__1>d&)>>	252.6	118.6	-134.0	-4.97	-3098.92	3
<<AsyncTaskMethodBuilder.SetResult(RootComponentOperationBatch)>>	252.6	118.6	-134.0	-4.97	-3098.92	3

[pavelsavara]

.netrace files

[pavelsavara]

Comparing rc1 and preview6, built in the same way as above. The workload is re-rendering page 3000 times in a loop.
The prev6 is 6362ms and rc1 6529ms of wall clock time. With fluctuations making this difference within error of measurement.
Depending on how many runs have run on the same tab. Likely jiterp and browser JIT influence.

preview6-G.zip
rc1-G.zip

[pavelsavara]

it would be a good idea to make sure there wasn't a change in the host environment for the benchmark either (e.g. chrome version change)

@lewing do you know which pipeline is running this test ? What VM image ? What version of chrome applies ?

[javiercn]

I wrote a benchmark for the renderer perf

Preview6

Method	RowCount	RenderIterations	Mean	Error	StdDev	Median	Op/s	Gen 0	Gen 1	Gen 2	Allocated
'Render table with multiple render cycles'	10	10	223.4 us	10.09 us	27.63 us	217.3 us	4,476.253	-	-	-	18 KB
'Render table with multiple render cycles'	10	100	1,614.9 us	26.63 us	38.20 us	1,619.6 us	619.248	-	-	-	164 KB
'Render table with multiple render cycles'	10	1000	10,640.4 us	2,475.81 us	7,300.00 us	6,360.1 us	93.981	-	-	-	1,571 KB
'Render table with multiple render cycles'	100	10	1,703.0 us	130.71 us	381.29 us	1,644.5 us	587.199	-	-	-	211 KB
'Render table with multiple render cycles'	100	100	8,780.1 us	1,813.87 us	5,348.24 us	5,952.7 us	113.893	-	-	-	1,228 KB
'Render table with multiple render cycles'	100	1000	38,841.9 us	811.87 us	2,263.16 us	38,001.8 us	25.745	-	-	-	12,183 KB
'Render table with multiple render cycles'	1000	10	5,347.7 us	441.02 us	1,229.40 us	5,200.3 us	186.998	-	-	-	1,535 KB
'Render table with multiple render cycles'	1000	100	38,063.0 us	756.41 us	1,493.08 us	37,686.1 us	26.272	-	-	-	14,088 KB
'Render table with multiple render cycles'	1000	1000	388,705.5 us	4,718.80 us	3,940.41 us	388,727.7 us	2.573	3000.0000	-	-	139,653 KB

Main

Method	RowCount	RenderIterations	Mean	Error	StdDev	Median	Op/s	Gen 0	Gen 1	Gen 2	Allocated
'Render table with multiple render cycles'	10	10	214.4 us	7.95 us	22.28 us	208.1 us	4,663.199	-	-	-	18 KB
'Render table with multiple render cycles'	10	100	1,584.1 us	28.41 us	46.68 us	1,580.2 us	631.288	-	-	-	163 KB
'Render table with multiple render cycles'	10	1000	10,305.4 us	2,514.94 us	7,415.37 us	5,754.2 us	97.037	-	-	-	1,572 KB
'Render table with multiple render cycles'	100	10	1,610.2 us	100.65 us	293.59 us	1,572.2 us	621.036	-	-	-	211 KB
'Render table with multiple render cycles'	100	100	8,114.1 us	1,679.69 us	4,952.61 us	6,393.4 us	123.242	-	-	-	1,229 KB
'Render table with multiple render cycles'	100	1000	41,689.1 us	1,165.81 us	3,363.62 us	40,802.2 us	23.987	-	-	-	12,183 KB
'Render table with multiple render cycles'	1000	10	5,598.0 us	453.13 us	1,240.44 us	5,292.1 us	178.636	-	-	-	1,533 KB
'Render table with multiple render cycles'	1000	100	43,431.2 us	1,118.46 us	3,227.01 us	42,149.2 us	23.025	-	-	-	14,093 KB
'Render table with multiple render cycles'	1000	1000	382,899.8 us	7,488.37 us	9,996.76 us	381,436.2 us	2.612	3000.0000	-	-	139,652 KB

Method	Branch	RowCount	RenderIterations	Mean	Error	StdDev	Median	Op/s	Gen 0	Gen 1	Gen 2	Allocated
'Render table with multiple render cycles'	preview6	10	10	223.4 us	10.09 us	27.63 us	217.3 us	4,476.253	-	-	-	18 KB
'Render table with multiple render cycles'	main	10	10	214.4 us	7.95 us	22.28 us	208.1 us	4,663.199	-	-	-	18 KB
'Render table with multiple render cycles'	preview6	10	100	1,614.9 us	26.63 us	38.20 us	1,619.6 us	619.248	-	-	-	164 KB
'Render table with multiple render cycles'	main	10	100	1,584.1 us	28.41 us	46.68 us	1,580.2 us	631.288	-	-	-	163 KB
'Render table with multiple render cycles'	preview6	10	1000	10,640.4 us	2,475.81 us	7,300.00 us	6,360.1 us	93.981	-	-	-	1,571 KB
'Render table with multiple render cycles'	main	10	1000	10,305.4 us	2,514.94 us	7,415.37 us	5,754.2 us	97.037	-	-	-	1,572 KB
'Render table with multiple render cycles'	preview6	100	10	1,703.0 us	130.71 us	381.29 us	1,644.5 us	587.199	-	-	-	211 KB
'Render table with multiple render cycles'	main	100	10	1,610.2 us	100.65 us	293.59 us	1,572.2 us	621.036	-	-	-	211 KB
'Render table with multiple render cycles'	preview6	100	100	8,780.1 us	1,813.87 us	5,348.24 us	5,952.7 us	113.893	-	-	-	1,228 KB
'Render table with multiple render cycles'	main	100	100	8,114.1 us	1,679.69 us	4,952.61 us	6,393.4 us	123.242	-	-	-	1,229 KB
'Render table with multiple render cycles'	preview6	100	1000	38,841.9 us	811.87 us	2,263.16 us	38,001.8 us	25.745	-	-	-	12,183 KB
'Render table with multiple render cycles'	main	100	1000	41,689.1 us	1,165.81 us	3,363.62 us	40,802.2 us	23.987	-	-	-	12,183 KB
'Render table with multiple render cycles'	preview6	1000	10	5,347.7 us	441.02 us	1,229.40 us	5,200.3 us	186.998	-	-	-	1,535 KB
'Render table with multiple render cycles'	main	1000	10	5,598.0 us	453.13 us	1,240.44 us	5,292.1 us	178.636	-	-	-	1,533 KB
'Render table with multiple render cycles'	preview6	1000	100	38,063.0 us	756.41 us	1,493.08 us	37,686.1 us	26.272	-	-	-	14,088 KB
'Render table with multiple render cycles'	main	1000	100	43,431.2 us	1,118.46 us	3,227.01 us	42,149.2 us	23.025	-	-	-	14,093 KB
'Render table with multiple render cycles'	preview6	1000	1000	388,705.5 us	4,718.80 us	3,940.41 us	388,727.7 us	2.573	3000.0000	-	-	139,653 KB
'Render table with multiple render cycles'	main	1000	1000	382,899.8 us	7,488.37 us	9,996.76 us	381,436.2 us	2.612	3000.0000	-	-	139,652 KB

[javiercn]

For reference, here is how to interpret the regression analysis report with overweight.

Regression Investigation with Overweight Analysis

Overweight analysis is a fairly simple technique in which the inclusive cost of all symbols from two traces are analyzed. Normally a time metric is used but any inclusive cost could work.

The idea is this: using the base and the test runs it's easy to get the overall size of the regression. Let's say it was 10%. From there you could take as your null hypothesis that everything is just 10% slower. What you're looking for is symbols that changed more than 10% and are therefore in some sense more responsible for the change. The overweight report in this case would simply compute the ratio of the actual growth compared to the expected growth of 10%. When you find symbols with greater than 100% overweight those are of great interest.

Suppose main calls f and g and does nothing else. Each takes 50ms for a total of 100ms. Now suppose f gets slower, to 60ms. The total is now 110, or 10% worse. How is this algorithm going to help? Well let's look at the overweights. Of course main is 100 going to 110, or 10%, it's all of it so the expected growth is 10 and the actual is 10. Overweight 100%. Nothing to see there. Now let's look at g, it was 50, stayed at 50. But it was 'supposed' to go to 55. Overweight 0/5 or 0%. And finally, our big winner, f, it went from 50 to 60, gain of 10. At 10% growth it should have gained 5. Overweight 10/5 or 200%. It's very clear where the problem is! But actually it gets even better.

Suppose that f actually had two children x and y. Each used to take 25ms but now x slowed down to 35ms. With no gain attributable to y, the overweight for y will be 0%, just like g was. But if we look at x we will find that it went from 25 to 35, a gain of 10 and it was supposed to grow by merely 2.5 so its overweight is 10/2.5 or 400%. At this point the pattern should be clear:

The overweight number keeps going up as you get closer to the root of the subtree which is the source of the problem. Everything below that will tend to have the same overweight. For instance if the problem is that x is being called one more time by f you'd find that x and all its children have the same overweight number.

This brings us to the second part of the technique. You want to pick a symbol that has a big overweight but is also responsible for a largeish fraction of the regression. So we compute its growth and divide by the total regression cost to get the responsibility percentage. This is important because sometimes you get leaf functions that had 2 samples and grew to 3 just because of sampling error. Those could look like enormous overweights, so you have to concentrate on methods that have a reasonable responsibility percentage and also a big overweight. The report automatically filters out anything with less than +/- 2% responsibility.

If I were to guess, I would look at something regarding int.ToString(). AddContent hasn't changed, BuildRenderTree I doubt has changed between versions (but we can see the generated code for the razor compiler) and same forall the add the other AddMarkup and so on.

[lewing]

There have definitely been regressions on the runtime side - dotnet/runtime#118499 but the timing of this doesn't track with those changes