Startup cost of XamlServices parsing is 27% slower on .NETCore than on .NET Framework

[dotMorten]

• .NET Core Version: 3.0 Preview1
• Windows version: 1803
• Does the bug reproduce also in WPF for .NET Framework 4.8?: No

Problem description:
I expected/hoped that with the XmlReader hopefully being Span<T> based. the XAML parser would be faster in .NET Core than the .NET Framework equivalent. However that's not what I'm seeing with this benchmark:

    public class BenchmarkTests
    {
        static readonly string xamlString = @"<MyObject xmlns=""clr-namespace:XamlBenchmark;assembly=XamlBenchmark"" StringProperty=""Hello World"" Int32Property=""1234"" DoubleProperty=""123.4567890"" FloatProperty=""-0.9876"" />";

        [Benchmark]
        public object Test1()
        {
            object instance = System.Xaml.XamlServices.Parse(xamlString);
            return instance;
        }
    }
    public class MyObject
    {
        public string StringProperty { get; set; }
        public int Int32Property { get; set; }
        public double DoubleProperty { get; set; }
        public float FloatProperty { get; set; }
    }

Here are the results:

BenchmarkDotNet=v0.11.3, OS=Windows 10.0.17763.1 (1809/October2018Update/Redstone5)
Intel Xeon CPU E5-1620 v3 3.50GHz, 1 CPU, 8 logical and 4 physical cores
  [Host]     : .NET Framework 4.7.2 (CLR 4.0.30319.42000), 64bit RyuJIT-v4.7.3190.0
  Job-FQKGZY : .NET Framework 4.7.2 (CLR 4.0.30319.42000), 64bit RyuJIT-v4.7.3190.0
  Job-YTBJBT : .NET Core 3.0.0-preview-27122-01 (CoreCLR 4.6.27121.03, CoreFX 4.7.18.57103), 64bit RyuJIT

Method	Runtime	Toolchain	Mean	Error	StdDev	Ratio	RatioSD
Test1	Clr	net472	363.3 us	7.139 us	7.639 us	1.00	0.00
Test1	Core	netcoreapp3.0	461.6 us	9.078 us	8.048 us	1.27	0.03

[fabiant3-zz]

Thanks @dotMorten. This is likely to be expected, as Core is not currently ngened. We'll address before Core3 ships.

[karelz]

cc @brianrob @billwert

[karelz]

Baiting @benaadams @AndreyAkinshin if they have interest to look for low-hanging fruit here 😉

[dotMorten]

Also looking at allocations by running this parse method many many times, I see this hit over 40 times per parsing:

And here's some of the CPU analysis:

Loading the assemblies' custom attributes takes a lot of time. The more assemblies that are loaded, the slower it will take. If you create a simple hello world app that tests this, .NET Framework loads 5 assemblies but .NET Core 3.0 preview loads 23 assemblies.

There's a XamlSchemaContext that could perhaps be reused since it's the class that loads all assemblies.

EDIT: If a XamlSchemaContext is used, .NET Core 3.0 preview is faster than .NET Framework 4.7.2 (tested 64-bit)

[richlander]

I love seeing this kind of issue. Great to see the focus on fundamentals.

[danmoseley]

Re GetCustomAttributes, it was improved by @NickCraver in dotnet/coreclr#20779 but that change would already be in preview 1.

@danmosemsft It's also 24 loaded assemblies (.NET Core 3.0 latest daily build) vs 5 loaded assemblies (.NET Framework 4.7.2).

If you patch System.Xaml to only check the first 5 returned assemblies (.NET Framework only loads 5 assemblies), then .NET Core 3.0 code executes faster.

So it seems the 5x number of assemblies is causing the slowdown. It has to execute more code.

Original .NET Core 3.0 daily build:

Name	Exc %	Exc	Inc %	Inc
module system.xaml <<system.xaml!XamlServices.Parse>>	24.0	1,073	91.6	4,090
module system.private.corelib <<system.private.corelib!Attribute.GetCustomAttributes>>	14.8	662	36.3	1,619
module coreclr <<coreclr!JIT_New>>	10.3	462	10.6	472
module clrjit <<clrjit!CILJit::compileMethod>>	5.4	239	5.4	243
module coreclr <<coreclr!JIT_NewArr1>>	5.4	239	5.7	253
module coreclr <<coreclr!ModuleHandle::ResolveType>>	5.2	234	5.2	234
module coreclr <<coreclr!MetaDataImport::GetCustomAttributeProps>>	5.2	231	5.6	248
module system.private.corelib <<system.private.corelib!CustomAttributeData.GetCustomAttributesInternal>>	4.9	219	22.9	1,023
module coreclr <<coreclr!Attribute::ParseAttributeArguments>>	4.1	183	5.4	241
module coreclr <<coreclr!MetaDataImport::Enum>>	3.4	152	4.0	178
module ntdll <<ntdll!LdrpDispatchUserCallTarget>>	2.6	116	2.6	116
module coreclr <<coreclr!MetaDataImport::GetParentToken>>	2.6	116	2.8	127

[brianrob]

Finally had a chance to look into this. Really great to see folks engaged here.

I was able to reproduce the difference and captured traces of 10K iterations of the parse operation to compare.

As was mentioned above, the biggest issue that I see is significantly higher cost in and caused
by Attribute.GetCustomAttributes. The higher cost shows up in both CPU usage in Attribute.GetCustomAttributes and in allocation helpers that are zeroing memory to support increased allocations in this path.

The biggest CPU usage differences are:

• Attribute.GetCustomAttributes: 560ms on Core vs. 265ms on Desktop = +111%
• Allocation helpers (JIT_New and JIT_NewArr1): 907ms on Core vs. 597ms on Desktop = +52%

Breaking down the allocations that contribute to the additional allocation helper CPU (as well as memory cost), these are the top 3 allocators:

• System.Reflection.CustomAttributeRecord[]
• System.Xaml.MS.Impl.XmlNsInfo
• Node[System.Reflection.Assembly.System.Xaml.MS.Impl.XmlNsInfo]

The first step here should be for this to be investigated from the reflection angle. @joshfree, can you get eyes on this from a reflection expert? I can share traces offline and help ramp someone up on the data.

[NickCraver]

Having taken some steps here already, it definitely seems like we can eliminate CustomAttributeRecord[] in some way. These are allocated only to be iterated in the caller in all cases, but the way they're populated is non-trivial to change. I have a branch locally that tried to eliminate these but it creates some very odd null refs in ways I didn't readily understand (but someone else may quickly see why I'm an idiot there).

If you're curious, this is where they're generated for a great many attribute code paths.

@brianrob

Attribute.GetCustomAttributes: 560ms on Core vs. 265ms on Desktop = +111%

This is probably because .NET Core loads 24 assemblies but .NET Framework only loads 5 assemblies. The code gets custom attributes of all loaded assemblies.

[brianrob]

@0xd4d, you're right - the iteration over all assemblies happens here:

wpf/src/Microsoft.DotNet.Wpf/src/System.Xaml/System/Xaml/XamlSchemaContext.cs

Line 1125 in 08d1133

private void UpdateXmlNsInfo()

As @NickCraver points out, there is possibly some optimization that can happen in the reflection path, but it is also true that there may need to be some work done in Xaml parsing to either limit the number of assemblies that get processed, or cache the results. Without a clear understanding of the WPF technology, it's not clear to me what should be done here. @fabiant3, are you the right person to look at this?