Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG] Extreme run time for adding instrumentation #1573

Closed
davhdavh opened this issue Dec 28, 2023 · 2 comments
Closed

[BUG] Extreme run time for adding instrumentation #1573

davhdavh opened this issue Dec 28, 2023 · 2 comments
Labels
as-designed Expected behaviour question This issue is a question

Comments

@davhdavh
Copy link

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

@github-actions github-actions bot added the untriaged To be investigated label Dec 28, 2023
@Bertk Bertk added question This issue is a question tenet-reporters Issue related to coverage output files(reporters) and removed tenet-reporters Issue related to coverage output files(reporters) untriaged To be investigated labels Jan 13, 2024
@Bertk
Copy link
Collaborator

Bertk commented Jan 13, 2024

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.

image

@Bertk Bertk added the waiting for customer Waiting for customer action label Jan 13, 2024
@daveMueller
Copy link
Collaborator

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.

@daveMueller daveMueller added as-designed Expected behaviour and removed waiting for customer Waiting for customer action labels Feb 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
as-designed Expected behaviour question This issue is a question
Projects
None yet
Development

No branches or pull requests

3 participants