[BUG] Extreme run time for adding instrumentation

davhdavh commented 6 months ago

Describe the bug

Some code constructs are extremely slow to Instrument:

        public static bool TryParse(
#if NETCOREAPP3_0_OR_GREATER
            [global::System.Diagnostics.CodeAnalysis.NotNullWhen(true)]
#endif
            string? name, 
            out global::TestProject1.MyEnum value, 
            bool ignoreCase, 
            bool allowMatchingMetadataAttribute)
        {
            if (ignoreCase)
            {
                switch (name)
                {
                    case string s when s.Equals(nameof(global::TestProject1.MyEnum.Test000), global::System.StringComparison.OrdinalIgnoreCase):
                        value = global::TestProject1.MyEnum.Test000;
                        return true;

Adding a couple of hundred enum values will make coverage take 30 minutes to complete the setup phase.

To Reproduce

using NetEscapades.EnumGenerators;
namespace TestProject1;

public class UnitTest1
{
   [Fact]
   public void Test1()
   {
      MyEnumExtensions.TryParse("something", out var v);
   }
}
[EnumExtensions]
public enum MyEnum
{
   Test000 = 0,
   Test001,
....
   Test199,
}

  <ItemGroup>
    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.6.0" />
    <PackageReference Include="NetEscapades.EnumGenerators" Version="1.0.0-beta08" />
    <PackageReference Include="xunit" Version="2.4.2" />
    <PackageReference Include="xunit.runner.visualstudio" Version="2.4.5">
      <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
      <PrivateAssets>all</PrivateAssets>
    </PackageReference>
    <PackageReference Include="coverlet.msbuild" Version="6.0.0">
      <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
      <PrivateAssets>all</PrivateAssets>
    </PackageReference>
  </ItemGroup>
  <PropertyGroup>
    <CollectCoverage>true</CollectCoverage>
    <CoverletOutputFormat>json,cobertura</CoverletOutputFormat>
    <IncludeTestAssembly>true</IncludeTestAssembly>
  </PropertyGroup>

Expected behavior Tests finish in 0.1msec

Actual behavior Attaching to process after a few min of running, shows it is "stuck" here (starting and pausing again, clearly shows it is still progressing through the loop, but it doesn't seem to ever finish):

    System.Linq.dll!System.Linq.Enumerable.WhereEnumerableIterator<Mono.Cecil.Cil.Instruction>.ToList() Line 3030   C#
>   coverlet.core.dll!Coverlet.Core.Symbols.CecilSymbolHelper.GetBranchPoints(Mono.Cecil.MethodDefinition methodDefinition = {Mono.Cecil.MethodDefinition}) Line 1030   C#
    coverlet.core.dll!Coverlet.Core.Instrumentation.Instrumenter.InstrumentIL(Mono.Cecil.MethodDefinition method = {Mono.Cecil.MethodDefinition}) Line 573  C#
    coverlet.core.dll!Coverlet.Core.Instrumentation.Instrumenter.InstrumentType(Mono.Cecil.TypeDefinition type = {Mono.Cecil.TypeDefinition}) Line 512  C#
    coverlet.core.dll!Coverlet.Core.Instrumentation.Instrumenter.InstrumentModule() Line 334    C#
    coverlet.core.dll!Coverlet.Core.Instrumentation.Instrumenter.Instrument() Line 149  C#
    coverlet.core.dll!Coverlet.Core.Coverage.PrepareModules() Line 135  C#
    coverlet.msbuild.tasks.dll!Coverlet.MSbuild.Tasks.InstrumentationTask.Execute() Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute()  Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(Microsoft.Build.BackEnd.ITaskExecutionHost taskExecutionHost = {Microsoft.Build.BackEnd.TaskExecutionHost}, Microsoft.Build.BackEnd.Logging.TaskLoggingContext taskLoggingContext = {Microsoft.Build.BackEnd.Logging.TaskLoggingContext}, Microsoft.Build.BackEnd.TaskHost taskHost = {Microsoft.Build.BackEnd.TaskHost}, Microsoft.Build.BackEnd.ItemBucket bucket = {Microsoft.Build.BackEnd.ItemBucket}, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask = ExecuteTaskAndGatherOutputs)   Unknown
    [Resuming Async Method] 
    System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start<Microsoft.Build.BackEnd.TaskBuilder.<ExecuteInstantiatedTask>d__25>(ref Microsoft.Build.BackEnd.TaskBuilder.<ExecuteInstantiatedTask>d__25 stateMachine) Line 55    C#
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.InitializeAndExecuteTask(Microsoft.Build.BackEnd.Logging.TaskLoggingContext taskLoggingContext = {Microsoft.Build.BackEnd.Logging.TaskLoggingContext}, Microsoft.Build.BackEnd.ItemBucket bucket = {Microsoft.Build.BackEnd.ItemBucket}, System.Collections.Generic.IDictionary<string, string> taskIdentityParameters = null, Microsoft.Build.BackEnd.TaskHost taskHost = {Microsoft.Build.BackEnd.TaskHost}, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask = ExecuteTaskAndGatherOutputs)    Unknown
    [Resuming Async Method] 
    System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start<Microsoft.Build.BackEnd.TaskBuilder.<InitializeAndExecuteTask>d__23>(ref Microsoft.Build.BackEnd.TaskBuilder.<InitializeAndExecuteTask>d__23 stateMachine) Line 55  C#
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteBucket(Microsoft.Build.BackEnd.TaskHost taskHost = {Microsoft.Build.BackEnd.TaskHost}, Microsoft.Build.BackEnd.ItemBucket bucket = {Microsoft.Build.BackEnd.ItemBucket}, Microsoft.Build.BackEnd.TaskExecutionMode howToExecuteTask = ExecuteTaskAndGatherOutputs, System.Collections.Generic.Dictionary<string, string> lookupHash = null)  Unknown
    [Resuming Async Method] 
    System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start<Microsoft.Build.BackEnd.TaskBuilder.<ExecuteBucket>d__19>(ref Microsoft.Build.BackEnd.TaskBuilder.<ExecuteBucket>d__19 stateMachine) Line 55    C#
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(Microsoft.Build.BackEnd.TaskExecutionMode mode = ExecuteTaskAndGatherOutputs, Microsoft.Build.BackEnd.Lookup lookup = {Microsoft.Build.BackEnd.Lookup}) Unknown
    [Resuming Async Method] 
    System.Private.CoreLib.dll!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start<Microsoft.Build.BackEnd.TaskBuilder.<ExecuteTask>d__18>(ref Microsoft.Build.BackEnd.TaskBuilder.<ExecuteTask>d__18 stateMachine) Line 55    C#
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(Microsoft.Build.BackEnd.Logging.TargetLoggingContext loggingContext = {Microsoft.Build.BackEnd.Logging.TargetLoggingContext}, Microsoft.Build.BackEnd.BuildRequestEntry requestEntry = {Microsoft.Build.BackEnd.BuildRequestEntry}, Microsoft.Build.BackEnd.ITargetBuilderCallback targetBuilderCallback = {Microsoft.Build.BackEnd.TargetBuilder}, Microsoft.Build.Execution.ProjectTargetInstanceChild taskInstance = Name="Coverlet.MSbuild.Tasks.InstrumentationTask" Condition="" ContinueOnError="" MSBuildRuntime="" MSBuildArchitecture="" #Parameters=14 #Outputs=1, Microsoft.Build.BackEnd.TaskExecutionMode mode = ExecuteTaskAndGatherOutputs, Microsoft.Build.BackEnd.Lookup inferLookup = {Microsoft.Build.BackEnd.Lookup}, Microsoft.Build.BackEnd.Lookup executeLookup = {Microsoft.Build.BackEnd.Lookup}, System.Threading.CancellationToken cancellationToken = IsCancellationRequested = false) Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ProcessBucket(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder = {Microsoft.Build.BackEnd.TaskBuilder}, Microsoft.Build.BackEnd.Logging.TargetLoggingContext targetLoggingContext = {Microsoft.Build.BackEnd.Logging.TargetLoggingContext}, Microsoft.Build.BackEnd.TaskExecutionMode mode = ExecuteTaskAndGatherOutputs, Microsoft.Build.BackEnd.Lookup lookupForInference = {Microsoft.Build.BackEnd.Lookup}, Microsoft.Build.BackEnd.Lookup lookupForExecution = {Microsoft.Build.BackEnd.Lookup})   Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetEntry.ExecuteTarget(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder = {Microsoft.Build.BackEnd.TaskBuilder}, Microsoft.Build.BackEnd.BuildRequestEntry requestEntry = {Microsoft.Build.BackEnd.BuildRequestEntry}, Microsoft.Build.BackEnd.Logging.ProjectLoggingContext projectLoggingContext = {Microsoft.Build.BackEnd.Logging.ProjectLoggingContext}, System.Threading.CancellationToken cancellationToken = IsCancellationRequested = false)    Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetBuilder.ProcessTargetStack(Microsoft.Build.BackEnd.ITaskBuilder taskBuilder = {Microsoft.Build.BackEnd.TaskBuilder})  Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.TargetBuilder.BuildTargets(Microsoft.Build.BackEnd.Logging.ProjectLoggingContext loggingContext = {Microsoft.Build.BackEnd.Logging.ProjectLoggingContext}, Microsoft.Build.BackEnd.BuildRequestEntry entry = {Microsoft.Build.BackEnd.BuildRequestEntry}, Microsoft.Build.BackEnd.IRequestBuilderCallback callback = {Microsoft.Build.BackEnd.RequestBuilder}, string[] targetNames = {string[5]}, Microsoft.Build.BackEnd.Lookup baseLookup = {Microsoft.Build.BackEnd.Lookup}, System.Threading.CancellationToken cancellationToken = IsCancellationRequested = false)    Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.RequestBuilder.BuildProject()   Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.RequestBuilder.BuildAndReport() Unknown
    Microsoft.Build.dll!Microsoft.Build.BackEnd.RequestBuilder.RequestThreadProc(bool setThreadParameters = true)   Unknown
    System.Private.CoreLib.dll!System.Threading.Tasks.Task<System.Threading.Tasks.Task>.InnerInvoke() Line 209  C#
    System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 138  C#
    System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal(ref System.Threading.Tasks.Task currentTaskSlot = Id = 7, Status = Running, Method = "System.Threading.Tasks.Task <StartBuilderThread>b__53_2()", Result = "{Not yet computed}", System.Threading.Thread threadPoolThread) Line 2190  C#
    System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteEntry() Line 2123 C#
    Microsoft.Build.dll!Microsoft.Build.BackEnd.RequestBuilder.DedicatedThreadsTaskScheduler.InjectThread.AnonymousMethod__6_0()    Unknown
    System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 138  C#

Configuration (please complete the following information): Please provide more information on your .NET configuration:

Which coverlet package and version was used? 6.0.0, but 3.20 has same problem
Which version of .NET is the code running on? dotnet 8, msbuild 17.8
What OS and version, and what distro if applicable? Can repro on both windows 11 and in linux docker build
What is the architecture (x64, x86, ARM, ARM64)? x64

Bertk commented 5 months ago

Hi, thank you for providing this information.

Could you please use the latest coverlet.msbuild preview version from coverlet nightly build and run your tests with it.
Do you see a similar effect if coverage for test projects is ignored <IncludeTestAssembly>false</IncludeTestAssembly>?
Maybe you can also update Microsoft.NET.Test.Sdk version.

daveMueller commented 4 months ago

I tried to create a repro for that (https://github.com/daveMueller/Coverlet_Issue_1573) but couldn't fully reproduce the described behavior. In the end it is the source generator from NetEscapades.EnumGenerators that increases instrumentation time as it generates around 3500 lines that all have sequence and branch points that we use to inject our tracker.

Best practice is to filter out source generators anyway because it's not possible to collect coverage for them. I added more information to the mentioned repo. I will close this issue for now as the instrumentation works as expected. If I missed something or am doing something wrong in the repro, please feel free to reopen this issue again.

coverlet-coverage / coverlet

[BUG] Extreme run time for adding instrumentation #1573