Performance regression in System.ServiceProcess.ServiceController, .Net Core App 2.1

[PaulHigin]

This was found in PowerShell Core6 (https://github.com/PowerShell/PowerShell) while investigating PowerShell cmdlet perf regression. I tracked the perf regression to this .Net type:

System.ServiceProcess.ServiceController

Using this type is approximately 30 times slower when running under .Net CoreApp 2.1

Repro steps:

using System;
using System.ServiceProcess;

namespace ConsoleApp3
{
    class Program
    {
        static void Main(string[] args)
        {
            System.Console.WriteLine("Starting loop");
            var start = DateTime.Now;

            for (var i=0; i<100; i++)
            {
                var winRMService = new ServiceController("WinRM");
                if (winRMService != null)
                {
                    var status = winRMService.Status;
                }
            }

            var end = DateTime.Now;

            System.Console.WriteLine("End loop");
            System.Console.WriteLine(String.Format("Time in milliseconds = {0}", (end - start).Milliseconds));
            System.Console.WriteLine("Press any key to continue");
            System.Console.ReadKey();
        }
    }
}

Results:
Under .Net Core App 2.1
Time in milliseconds = 714

Under .Net Full CLR
Time in milliseconds = 24

Expected:
Use of ServiceController type should have approximately the same performance between each version of .Net.

[karelz]

By "under .NET Standard" do you mean you run it against .NET Core? Which version of .NET Core and .NET Framework?
Can you please create BenchmarkDotNet perf test and provide the results here? (it will do lots of heavy lifting for you)

cc @valenis @brianrob @adamsitnik

[adamsitnik]

I wrote small micro-benchmark to verify it. It proves that on .NET Core given property (.Status) is actually 23% faster:

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

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFrameworks>net461;netcoreapp2.0;netcoreapp2.1</TargetFrameworks>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="BenchmarkDotNet" Version="0.11.1" />
    <PackageReference Include="System.ServiceProcess.ServiceController" Version="4.5.0" />
  </ItemGroup>

</Project>

using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Configs;
using BenchmarkDotNet.Jobs;
using BenchmarkDotNet.Running;
using BenchmarkDotNet.Toolchains.CsProj;
using System.ServiceProcess;

namespace ServiceControllerPerf
{
    class Program
    {
        static void Main(string[] args) 
            => BenchmarkRunner.Run<Perf>(
                DefaultConfig.Instance
                  .With(Job.Clr.AsBaseline())
                  .With(Job.Core.With(CsProjCoreToolchain.NetCoreApp20).WithId("Core 2.0"))
                  .With(Job.Core.With(CsProjCoreToolchain.NetCoreApp21).WithId("Core 2.1")));
    }

    public class Perf
    {
        private readonly ServiceController winRMService = new ServiceController("WinRM");

        [Benchmark]
        public ServiceControllerStatus GetStatus() => winRMService.Status;
    }
}

dotnet run -c Release -f netcoreapp2.1

BenchmarkDotNet=v0.11.1, OS=Windows 10.0.17134.228 (1803/April2018Update/Redstone4)
Intel Xeon CPU E5-1650 v4 3.60GHz (Max: 2.10GHz), 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=2.1.301
  [Host]   : .NET Core 2.1.1 (CoreCLR 4.6.26606.02, CoreFX 4.6.26606.05), 64bit RyuJIT
  Clr      : .NET Framework 4.7.2 (CLR 4.0.30319.42000), 64bit RyuJIT-v4.7.3132.0
  Core 2.0 : .NET Core 2.0.7 (CoreCLR 4.6.26328.01, CoreFX 4.6.26403.03), 64bit RyuJIT
  Core 2.1 : .NET Core 2.1.1 (CoreCLR 4.6.26606.02, CoreFX 4.6.26606.05), 64bit RyuJIT

Method	Job	Mean	Error	StdDev	Scaled
GetStatus	Clr	10.996 ns	0.0461 ns	0.0409 ns	1.00
GetStatus	Core 2.0	8.496 ns	0.0237 ns	0.0210 ns	0.77
GetStatus	Core 2.1	8.469 ns	0.0406 ns	0.0360 ns	0.77

@PaulHigin which profiler did you use? Could you share some traces?

[PaulHigin]

Sorry! I incorrectly stated .Net Standard as the framework we are using. Actually we are using .Net Core App 2.1 (with version 2.1.2 framework runtime version).

I didn't bother running a profiler since the slow down is so pronounced. Simply running the simple loop shown in the repro steps demonstrates the perf difference.

I update the title and repro steps to indicate the correct version of .Net having the perf issue.

Thanks.

[PaulHigin]

Here is the dotnet version info with the perf issue:

PS E:\Git_Repos\PowerShell2\powershell\src\System.Management.Automation> dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   2.1.302
 Commit:    9048955601

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.17134
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Users\paulhi\AppData\Local\Microsoft\dotnet\sdk\2.1.302\

Host (useful for support):
  Version: 2.1.2
  Commit:  811c3ce6c0

.NET Core SDKs installed:
  2.1.302 [C:\Users\paulhi\AppData\Local\Microsoft\dotnet\sdk]
  2.1.400 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.2 [C:\Users\paulhi\AppData\Local\Microsoft\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.2 [C:\Users\paulhi\AppData\Local\Microsoft\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.2 [C:\Users\paulhi\AppData\Local\Microsoft\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download
PS E:\Git_Repos\PaulHigin\PowerShell2\powershell\src\System.Management.Automation>

[karelz]

@PaulHigin are you able to reproduce it with .NET Core 2.1.1? That's what @adamsitnik used and saw no perf problem.
Can you run the BenchmarkDotNet test @adamsitnik created and paste the results here? (even on 2.1.2)

[adamsitnik]

@PaulHigin @karelz please excuse me, I have missed the fact that the benchmark provided by @PaulHigin includes the creation of ServiceController. I have fixed that and confirmed, that on .NET Core 2.0 and 2.1 it works 14 times slower.

[Benchmark]
public ServiceControllerStatus GetStatus()
{
    var winRMService = new ServiceController("WinRM");
    if (winRMService != null)
    {
        return winRMService.Status;
    }

    return default(ServiceControllerStatus);
}

BenchmarkDotNet=v0.11.1, OS=Windows 10.0.17134.228 (1803/April2018Update/Redstone4)
Intel Xeon CPU E5-1650 v4 3.60GHz, 1 CPU, 12 logical and 6 physical cores
.NET Core SDK=2.1.301
  [Host]   : .NET Core 2.1.1 (CoreCLR 4.6.26606.02, CoreFX 4.6.26606.05), 64bit RyuJIT
  Core 2.0 : .NET Core 2.0.7 (CoreCLR 4.6.26328.01, CoreFX 4.6.26403.03), 64bit RyuJIT
  Core 2.1 : .NET Core 2.1.1 (CoreCLR 4.6.26606.02, CoreFX 4.6.26606.05), 64bit RyuJIT
  ShortRun : .NET Framework 4.7.2 (CLR 4.0.30319.42000), 64bit RyuJIT-v4.7.3132.0

IterationCount=3  LaunchCount=1  WarmupCount=3  

Method	Runtime	Toolchain	Mean	Scaled
GetStatus	Core	.NET Core 2.0	3,967.7 us	14.01
GetStatus	Core	.NET Core 2.1	4,049.1 us	14.29
GetStatus	Clr	Default	284.4 us	1.00

[karelz]

Thanks @adamsitnik! The remaining step is -- why does it show on hot path in a PowerShell scenario? What is the real-world scenario when it is called more than 100x in short period of time @PaulHigin?

[PaulHigin]

This affects the wsman: drive, which in turn affects PowerShell remoting endpoint configuration.

(measure-command { dir wsman: -r }).seconds
10
# This is more than 10x slower than PowerShell with Full CLR

(measure-command { Get-PSSessionConfiguration }).seconds
12
# This is 12x slower than PowerShell with Full CLR

Thanks.

[karelz]

@PaulHigin what does it do internally? Why does it create so many objects?
What are the absolute numbers here?

[PaulHigin]

The wsman drive provider continuously monitors the state of the WinRM service, on which it relies, when accessing drive information. I didn't write the code but I have looked at it. The ServiceController.Status property appears to be a snap shot of the status at that time, and getting the latest status requires creating a new ServiceController object, which is why it gets created so many times.

[karelz]

@PaulHigin so how many times is it called per second? I want to make sure we are not optimizing something which has a perf bug in it or is extreme corner case.

[PaulHigin]

It varies depending on how the drive is used. This code has not changed in many years, and relies on this object working in a performant manner. The .Net Core change in performance is an order of magnitude worse than before and I feel it should be addressed by the .Net Core team.

[karelz]

@PaulHigin we will need more details than that. The fact something had specific perf characteristic for years does not mean we have to have them in Core. That is way too close to bug-by-bug compatibility, which no one wants.

That said, if there is something obviously wrong in Core that can be fixed and it improves perf, then sure. However, if it is tricky and there are reasons for the perf to be worse, we need to understand the perf impact on real-world scenarios as that is what matters.
If the script is buggy/inefficient, then I'd be fine making it more inefficient/buggy on Core even if it didn't change in years.
Please help us make the right call by providing more details about the scenario and why it is important scenario.

[PaulHigin]

@karelz At the very least I feel you should look into what has changed between FullCLR and Core. It may be something that can be remedied easily. A perf regression of this magnitude is likely to affect other customers.
@SteveL-MSFT , @TravisEz13