[Perf] XmlSerializer.Deserialize() regression between release/2.0.0 and release/2.1

[adamsitnik]

This is a follow up of https://github.com/dotnet/coreclr/issues/16627

There is a performance regression of XmlSerializer.Deserialize(Stream) for 2.1 compared to 2.0. For Windows it's from 10 to 30%, for Linux it's from 50% to 100%.

I did a small investigation, it looks that few calls to system.private.xml!System.Marvin.ComputeHash(System.ReadOnlySpan<Byte>, UInt64) are responsible for that.

2.1 most time-consuming methods by name:

2.0 most time-consuming methods by name:

Methods which call Marvin.ComputeHash

Later I am going to provide a separate PR with a new benchmark for our benchmarking suite. For now please use following plain simple code:

using System;
using System.Diagnostics;
using System.IO;
using System.Xml.Serialization;

namespace XmlDeserializationRegression
{
    class Program
    {
        static void Main(string[] args)
        {
            var serializer = new XmlSerializer(typeof(LoginViewModel));

            using (var memoryStream = new MemoryStream(capacity: short.MaxValue))
            {
                serializer.Serialize(memoryStream, CreateLoginViewModel());

                Benchmark(memoryStream, serializer, 1, "Warmup");
                Benchmark(memoryStream, serializer, 10000, "Actual run");
            }

            var coreclrAssemblyInfo = FileVersionInfo.GetVersionInfo(typeof(object).Assembly.Location);
            var corefxAssemblyInfo = FileVersionInfo.GetVersionInfo(typeof(System.Text.RegularExpressions.Regex).Assembly.Location);

            Console.WriteLine($"CoreCLR {coreclrAssemblyInfo.FileVersion}, CoreFX {corefxAssemblyInfo.FileVersion}");
        }

        private static void Benchmark(Stream stream, XmlSerializer xmlSerializer, int invocationCount, string displayText)
        {
            object deserialized = null;

            GC.Collect();
            GC.WaitForPendingFinalizers();
            GC.Collect();

            var timer = Stopwatch.StartNew();

            for (int i = 0; i < invocationCount; i++)
            {
                stream.Position = 0;
                deserialized = xmlSerializer.Deserialize(stream);
            }

            TimeSpan avg = timer.Elapsed / invocationCount;
            Console.WriteLine($"{displayText}: Average elapsed milliseconds: {avg.TotalMilliseconds}");

            GC.KeepAlive(deserialized);
        }

        private static LoginViewModel CreateLoginViewModel()
            => new LoginViewModel
            {
                Email = "name.familyname@not.com",
                Password = "abcdefgh123456!@",
                RememberMe = true
            };
    }

    public class LoginViewModel
    {
        public string Email { get; set; }
        public string Password { get; set; }
        public bool RememberMe { get; set; }
    }
}

The csproj:

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFrameworks>netcoreapp2.1;netcoreapp2.0</TargetFrameworks>
    <RuntimeIdentifier>win-x64</RuntimeIdentifier>
  </PropertyGroup>

</Project>

To run the benchmark:

dotnet run -c Release -f netcoreapp2.0 and dotnet run -c Release -f netcoreapp2.0

Some Flame Graphs from PerfView which give good overview:

For 2.0:

For 2.1:

The problematic part:

It's my first perf investigation as a new member of the .NET Performance Team, please let me know if something is missing or wrong.

[stephentoub]

If this was due to Marvin.ComputeHash calls, maybe this regression was addressed by dotnet/coreclr#16654 and dotnet/coreclr#16659, which are meant to address https://github.com/dotnet/corefx/issues/27485?

[adamsitnik]

@stephentoub it seems that you are right!

I just used BenchmarkDotNet following the instructions from: dotnet/corefx#27164

And compared 2.0.5 vs 2.1.preview vs latest packages on MyGet (CoreCLR 4.6.26301.09, CoreFX 4.6.26228.08):

BenchmarkDotNet=v0.10.12.449-nightly, OS=Windows 10 Redstone 3 [1709, Fall Creators Update] (10.0.16299.248)
Intel Core i7-3687U CPU 2.10GHz (Ivy Bridge), 1 CPU, 4 logical cores and 2 physical cores
Frequency=2533323 Hz, Resolution=394.7385 ns, Timer=TSC
.NET Core SDK=2.1.300-preview2-008162
  [Host]     : .NET Core 2.1.0-preview2-26131-06 (CoreCLR 4.6.26130.05, CoreFX 4.6.26130.01), 64bit RyuJIT
  Job-VQCTZN : .NET Core ? (CoreCLR 4.6.26301.09, CoreFX 4.6.26228.08), 64bit RyuJIT
  2.0        : .NET Core 2.0.5 (CoreCLR 4.6.26020.03, CoreFX 4.6.26018.01), 64bit RyuJIT
  2.1        : .NET Core 2.1.0-preview2-26131-06 (CoreCLR 4.6.26130.05, CoreFX 4.6.26130.01), 64bit RyuJIT

Runtime=Core  LaunchCount=1  TargetCount=3  
WarmupCount=3  

Method	Job	Toolchain	IsBaseline	Mean	Error	StdDev	Scaled	ScaledSD	Gen 0	Allocated
XmlSerializer	Default	myget builds	Default	9.130 us	3.9029 us	0.2205 us	0.92	0.02	2.8992	5.95 KB
XmlSerializer	2.0	.NET Core 2.0	True	9.972 us	0.6910 us	0.0390 us	1.00	0.00	2.9144	5.98 KB
XmlSerializer	2.1	.NET Core 2.1	Default	12.558 us	7.2185 us	0.4079 us	1.26	0.03	2.8992	5.95 KB

I am going to check it once again tomorrow to be 100% sure. If the regression is gone I am going to close the issue.

[adamsitnik]

I have verified that the initial regression of 30% for Windows (#27636) was fixed by dotnet/coreclr#16654 and dotnet/coreclr#16659

Unfortunately, this is not true for Linux (at least Ubuntu 16.04). XmlSerializer.Deserialize() is 100% slower for Linux, when comparing 2.0 and 2.1. I created a separate issue for that: dotnet/corefx#27786

[AndyAyersMS]

I would hope when taking dotnet/coreclr#16659 into account that master would now be a bit faster than 2.0 -- the change in dotnet/coreclr#16654 should have undone the regression all by itself.

[AndyAyersMS]

Saw you left a note over in dotnet/coreclr#16659 that you see ~3% or so from this change, so is master now 3% faster than 2.0?

[adamsitnik]

I would hope when taking dotnet/coreclr#16659 into account that master would now be a bit faster than 2.0 -- the change in dotnet/coreclr#16654 should have undone the regression all by itself.

@AndyAyersMS Sorry for not making myself clear. Master is actually a little bit faster (few %) than 2.0 now. So for Windows not only the regression is gone, but it's also few % faster (depending on the scenario). For Linux (at least Ubuntu 16.04) it's still 100% slower.