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

Test's not working when using Coverlet Collector #1246

Closed
kastroph opened this issue Nov 4, 2021 · 33 comments
Closed

Test's not working when using Coverlet Collector #1246

kastroph opened this issue Nov 4, 2021 · 33 comments
Labels
tenet-performance Performance related issue

Comments

@kastroph
Copy link

kastroph commented Nov 4, 2021

Hi,

I'm trying to use the coverlet collector and it does not exit the tests. I have 85 tests that take about 35 seconds to run. But when I run dotnet test --collect:"XPlat Code Coverage" it runs forever I have to manually close the process. Coverlet is working fine.

The project is in dot net 5.0.

Coverlet output
Calculating coverage result...
Generating report 'ERP.Service.xUnit.Test\coverage.json'
+-------------------------------+--------+--------+--------+
| Module | Line | Branch | Method |
+-------------------------------+--------+--------+--------+
| ERP.Core | 38.81% | 3.19% | 19.8% |
+-------------------------------+--------+--------+--------+
| ERP.Infrastructure | 0% | 0% | 0% |
+-------------------------------+--------+--------+--------+
| ERP.Repositories | 20.28% | 24.1% | 34.23% |
+-------------------------------+--------+--------+--------+
| ERP.Services | 38.02% | 23.25% | 32.46% |
+-----------------------------+--------+--------+--------+
| ERP.Services.xUnit.Test | 99.82% | 90.62% | 99% |
+-------------------------------+--------+--------+--------+

+---------+--------+--------+--------+
| | Line | Branch | Method |
+---------+--------+--------+--------+
| Total | 0.1% | 20.65% | 19.06% |
+---------+--------+--------+--------+
| Average | 39.38% | 28.23% | 37.09% |
+---------+--------+--------+--------+

Output for dotnet test --collect:"XPlat Code Coverage"

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.

@daveMueller
Copy link
Collaborator

Seems to be the same issue as #1044

@kastroph
Copy link
Author

kastroph commented Nov 5, 2021

@daveMueller Thanks,

I had a look at #1044 I don't think it's the same issue. we don't have any I/O in our projects under test.

I'll take a copy of the source code and see if I can find where it's getting stuck over the weekend

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

@kastroph one question, in your output above I see the table that we emit with msbuild integration and not with collectors and the instrumentation engine is the same so it's not clear to me why should work with msbuild and not with collectors, can you provide your full command line?
Also can you add verbose logging using --diag:log.txt https:/MarcoRossignoli/coverlet/blob/master/Documentation/Troubleshooting.md#collectors-integration
There's a way to produce a dump in case of hang https://docs.microsoft.com/en-us/dotnet/core/tools/dotnet-test --blame-hang
You can also take a dump of hang process using https://docs.microsoft.com/en-us/sysinternals/downloads/procdump

LOGS/DUMP CONTAINS SENSITIVE INFORMATIONS LIKE KEYS ​ETC...SO DON'T ATTACH HERE.

You can open dump with Visual Studio and log with notepad. If you're not able to find out where code hangs(you should see it in stacks) I can help but we need to find a way to share dump/logs and you have to trust me, in that case we can sync offline, DM me here https://twitter.com/MarcoRossignoli if needed.

@MarcoRossignoli MarcoRossignoli added the waiting for customer Waiting for customer action label Nov 6, 2021
@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli Thank you for showing an interest in my issue it is appreciated.

I have attached log.txt file from: dotnet test --collect:"XPlat Code Coverage" --diag:log.txt. I have parsed out any identifying information.

dotnet test /p:CollectCoverage=true /p:CoverletOutputFormat=cobertura works fine and outputs:
image

log.txt

Sorry I don't have a Twitter account :(

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

@kastroph you should get 3 log files, one for main test driver one for host and one for data collector (where coverlet resides) I see only one file attached, is it the only file generated?

We can use gitter.

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli That's my bad!

I have attached the missing file
log.host.21-11-06_13-49-48_42567_5.txt
s
log.datacollector.21-11-06_13-48-31_56943_5.txt

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

Which version of coverlet are you using?
Can you zip and send logs also for dotnet test /p:CollectCoverage=true /p:CoverletOutputFormat=cobertura same diag config.

Not needed...looks like it hangs on collector during report generation...but from logs isn't possible understand where it stucks we need to get a dump.

In log.datacollector.21-11-06_13-48-31_56943_5.txt after hit file deletion(second to last line) we expect generation of file but it stucks until parent process exits(I think when you stop with ctrl+c on console).

You should run the test and when it hangs(some seconds) you should find a process called datacollector.exe as child of dotnet.exe that is the process for which to take the dump. After you should open in VS and take a look at stacks.

A normal log should be something like

TpTrace Verbose: 0 : 12296, 1, 2021/11/06, 15:58:05.190, 9120886030, datacollector.dll, [coverlet]Hit file 'C:\Users\mrossignoli\AppData\Local\Temp\ClassLibrary1_caa2c8d8-0589-4152-a05c-4e34193c1914' deleted
...
TpTrace Information: 0 : 12296, 1, 2021/11/06, 15:58:05.226, 9121246374, datacollector.dll, [coverlet]CoverletCoverageDataCollector: Saved coverage report to path: 'C:\Users\mrossignoli\AppData\Local\Temp\87c78d9c-a39d-40ef-8da0-420f0414bd86\coverage.cobertura.xml'
...
TpTrace Information: 0 : 22504, 1, 2021/11/06, 15:58:05.234, 9121329227, datacollector.dll, DataCollectionRequestHandler.ProcessRequests : DataCollection completed

in your case

TpTrace Verbose: 0 : 3376, 1, 2021/11/06, 13:49:53.691, 1527661733144, datacollector.dll, [coverlet]Hit file 'C:\Users\User\AppData\Local\Temp\Project.Core_ac8c1e45-e7fb-4b6c-9bc8-9279b142e04b' deleted
TpTrace Information: 0 : 3376, 5, 2021/11/06, 14:04:01.677, 1536141587252, datacollector.dll, DataCollector: ParentProcess '18396' Exited.

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli hmmmm I'm not finding a process for DataCollector. exe

From the log, I think it must be throwing an exception then closing the PID

image

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

Sry my fault you're using dotnet test and not vstest.console.exe in that case datacollector is hosted into dotnet.exe process....so you should open using process explorer(as admin) https://docs.microsoft.com/en-us/sysinternals/downloads/process-explorer and you should find a dotnet.exe process child with this commandline:

"C:\Program Files\dotnet\dotnet.exe" exec --runtimeconfig "C:\Program Files\dotnet\sdk\xxx\datacollector.runtimeconfig.json" --depsfile "C:\Program Files\dotnet\sdk\xxx\datacollector.deps.json" "C:\Program Files\dotnet\sdk\xxx\datacollector.dll" --port 53189 --parentprocessid 20572 --diag "C:\git\localPlayground\TestProject\log.datacollector.21-11-06_16-17-08_56989_5.txt" --tracelevel 4 

datacollector.dll is our guy, this process should be the last in the chain of processes and it's the blocking process
With process explorer if you click the right button on the process(dotnet.exe that hosts datacollector.dll) in the context menu you can take a process dump.

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli The test host starts up then exits very quickly I took a dump file but it's only windows stuff in it

image

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

you don't have to take the dump of testhost but of datacollector is another process, if you run in console and wait for hang you'll find the process there and you can take the dump because will be alive.
Architecture of test platform is

vstest.console process(main driver)
-> testhost process
-> datacollector process = this is the hanging one

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli can you send a screenshot of what I should be looking for? I'm struggling to find it in Process Explorer

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

Steps:

  1. Run
dotnet test --collect:"XPlat Code Coverage"

Wait for some seconds/minutes it should hang with console message above

  1. Open process exporer(admin) and drag&drop this symbol on the hanging terminal windows

image

This should bring you to the parent process(terminal) with some dotnet.exe children.

  1. If your app is hanging like the image you sent above last process should be the process that hosts datacollector, you can confirm it clicking on it and the command line should be something like
"C:\Program Files\dotnet\dotnet.exe" exec --runtimeconfig "C:\Program Files\dotnet\sdk\xxx\datacollector.runtimeconfig.json" --depsfile "C:\Program Files\dotnet\sdk\xxx\datacollector.deps.json" "C:\Program Files\dotnet\sdk\xxx\datacollector.dll" --port 53189 --parentprocessid 20572 --diag "C:\git\localPlayground\TestProject\log.datacollector.21-11-06_16-17-08_56989_5.txt" --tracelevel 4 

That is the process for what to take the dump.

Anyway if it's hanging it means that on of the dotnet.exe process under terminal is blocking and so you should be able to find the last one that is blocking the chain. If normal case all dotnet.exe processes will die after test ends.
I'm not able to repro because I don't have hanging collector sample so process will die in some milliseconds with no hanging processes.

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli I have the process tree

image

I'm a bit confused by step 3 sorry

@MarcoRossignoli
Copy link
Collaborator

Double click on dotnet.exe and process explorer will show you che "command line" for that process. If the command line contains datacollector.dll as argument it means that the process is hosting datacollector part of test platform and so it's the process hanging.
That is the process for which take the dump, looking at your windows I suppose is the last dotnet.exe(6% consumptions...maybe is into some infinite loop).

Right click on process(menu) -> Create Dump -> Create full dump

@MarcoRossignoli
Copy link
Collaborator

Also that 6GB mem consumptions looks suspicious

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli oh got this out of the console

Passed Alter.ERP.Services.Invoices.Tests.InvoiceServiceTests.IssueInvoice_IssuesPartialInvoice(orderGroupChoice: OrderGroupsOnly) [13 ms]
[xUnit.net 00:00:04.68] Finished: xUnit.Test
Data collector 'Blame' message: The specified inactivity time of 2 minutes has elapsed. Collecting hang dumps from testhost and its child processes.
Data collector 'Blame' message: Data collector caught an exception of type 'System.InvalidOperationException': 'Process has exited, so the requested information is not available.'. More details: Blame: Creating hang dump failed with error...
Data collector 'Blame' message: Data collector caught an exception of type 'System.IO.FileNotFoundException': 'Collect dump was enabled but no dump file was generated.'. More details: Blame: Collecting hang dump failed with error...

@kastroph kastroph closed this as completed Nov 6, 2021
@kastroph kastroph reopened this Nov 6, 2021
@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

You should remove the blame argument...blame collector took dump of test host but looks like your problem is on collector and not into test host(so after hang timeout fires blame collector tries to dump testhost but it's gone and will fail). So run the command line without --blame and took the dump manually for the last dotnet process in the chain that contains datacollector.dll

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

Also that 6GB mem consumptions looks suspicious

It's probably from the sins of the project. I can make it use 40Gb if I try. The team I have taken over has poor knowledge of SOLID and best practices. I'm hoping to use Coverlet to encourage testing.

Okay I think I have the dump

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

Is there a way I can debug the collector in my test project? I think it's probably the only way we will get to the bottom of it. I'm not that familiar with the architecture. I suspect I'll need to see the stack trace of test runner

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\dotnet.exe'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\ntdll.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\kernel32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\KernelBase.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\ucrtbase.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\host\fxr\6.0.0-rc.2.21480.5\hostfxr.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\advapi32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\msvcrt.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\sechost.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\rpcrt4.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\hostpolicy.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\coreclr.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\ole32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\combase.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\gdi32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\win32u.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\gdi32full.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\msvcp_win.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\user32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\oleaut32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\imm32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\bcryptprimitives.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Private.CoreLib.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\clrjit.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\kernel.appcore.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\datacollector.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Microsoft.TestPlatform.PlatformAbstractions.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Microsoft.VisualStudio.TestPlatform.Common.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Microsoft.VisualStudio.TestPlatform.ObjectModel.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Microsoft.TestPlatform.CommunicationUtilities.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\netstandard.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Newtonsoft.Json.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Collections.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.Serialization.Formatters.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Collections.Concurrent.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Threading.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Microsoft.TestPlatform.CoreUtilities.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Private.Uri.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.Extensions.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\icu.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Diagnostics.TraceSource.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Diagnostics.Process.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.ComponentModel.Primitives.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Memory.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Threading.ThreadPool.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\Microsoft.Win32.Primitives.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.InteropServices.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Net.Primitives.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Net.Sockets.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Diagnostics.Tracing.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\ws2_32.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\mswsock.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\wshunix.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Threading.Overlapped.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\bcrypt.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Linq.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Linq.Expressions.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.Numerics.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.ComponentModel.TypeConverter.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.ObjectModel.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.Serialization.Primitives.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Data.Common.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Xml.ReaderWriter.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Private.Xml.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.ComponentModel.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Reflection.Emit.ILGeneration.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Reflection.Emit.Lightweight.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Reflection.Primitives.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.InteropServices.RuntimeInformation.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.IO.FileSystem.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\NuGet.Frameworks.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Runtime.Loader.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\coverlet.collector.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\coverlet.core.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Extensions\Microsoft.TestPlatform.Extensions.BlameDataCollector.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\sdk\6.0.100-rc.2.21505.57\Extensions\Microsoft.TestPlatform.Extensions.EventLogCollector.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\mscorlib.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Xml.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\Microsoft.Extensions.DependencyInjection.Abstractions.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.ComponentModel.EventBasedAsync.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\Microsoft.Extensions.DependencyInjection.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Text.RegularExpressions.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\Microsoft.Extensions.FileSystemGlobbing.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Reflection.Metadata.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Collections.Immutable.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.IO.MemoryMappedFiles.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Text.Encoding.Extensions.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Windows\System32\ntmarta.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\Mono.Cecil.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\Microsoft.Extensions.DependencyModel.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.IO.Compression.dll'.
'dotnet.exe' (Win32): Loaded 'C:\Users\User.nuget\packages\coverlet.collector\3.0.2\build\netstandard1.0\Mono.Cecil.Rocks.dll'.
The thread 0x2bdc has exited with code 0 (0x0).
The thread 0x65ac has exited with code 0 (0x0).
The thread 0x5818 has exited with code 0 (0x0).
The thread 0x6358 has exited with code 0 (0x0).
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.IO.Compression.Native.dll'.
The thread 0x1a14 has exited with code 0 (0x0).
'dotnet.exe' (Win32): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.0-rc.2.21480.5\System.Threading.Thread.dll'.
The thread 0x55a8 has exited with code 0 (0x0).
The thread 0x691c has exited with code 0 (0x0).
The thread 0x6040 has exited with code 0 (0x0).
The thread 0xc7c has exited with code 0 (0x0).
The thread 0x4910 has exited with code 0 (0x0).

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

Are you opening with Visual Studio? You should be able to see the threads/stacks and where are stuck, usually in hanging situation there is few(one?) actively running that is looping(if cpu is constantly above 0%) or waiting something(cpu is constantly close to 0%).
You can debug collector it's a bit advanced https:/MarcoRossignoli/coverlet/blob/master/Documentation/Troubleshooting.md#enable-collector-instrumentation-debugging

if you set set COVERLET_DATACOLLECTOR_OUTOFPROC_DEBUG=1 and re-run the dotnet test you can attach VS and debug.

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

If you want to share dump with me we can talk on gitter and you can send me on onedrive authenticated link https://gitter.im/ clearly only in case you need it.

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

Discussed off-line and after dump analysis looks like it's a perf issue, coverlet is stuck inside CalculateCoverage part

foreach (HitCandidate hitCandidateToCompare in result.HitCandidates.Where(x => x.docIndex.Equals(hitCandidate.docIndex)))

Looks like the instrumented assembly is very big, first time that we have a perf issue during coverage calculation. Anyway we can improve here with a better data structure, dictionary or binary search.

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

@MarcoRossignoli Thank you so much for your support today <3

I excluded the project that I thought would be a problem for performance.

If you would like a one to one codeshare session I'm happy to authorise it to improve Coverlet

image

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

Glad to see that we found the culprit!
I can try to understand how to improve this part and after we can try to give it a try with your special case.
How big is the assembly in MB?
Excluding that lib speeded up all the things?

Thanks a lot for all the informations.

@MarcoRossignoli MarcoRossignoli removed the waiting for customer Waiting for customer action label Nov 6, 2021
@MarcoRossignoli MarcoRossignoli added the tenet-performance Performance related issue label Nov 6, 2021
@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

Solution 1.81 GB
Problem assembly 438 MB (Web UI)

@MarcoRossignoli
Copy link
Collaborator

Ok let me know if you're able to run it on your local to understand how many time is need.

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

Excluding the web project

Test Run Successful.
Total tests: 82
Passed: 82
Total time: 5.1006 Seconds

only 2 seconds slower than just running the tests in the command line

@MarcoRossignoli
Copy link
Collaborator

Ok let's try with the web project if possible. Only to understand if it's possible set a meaningful timeout on CI and on test platform(maybe it will timeout after a while I need to check).

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

The web project is full of static references tends of thousands. If you build on an Intel i5 the build time is 30 minutes

@MarcoRossignoli
Copy link
Collaborator

MarcoRossignoli commented Nov 6, 2021

Ok got it...so it's definitely an edge case...looks like the perf issue is also on build.
Maybe also for maintainability you could think to split in different dlls, that would speed up build/testing/coverage thanks to parallel execution.

@kastroph
Copy link
Author

kastroph commented Nov 6, 2021

I definitely would not lose sleep over it unless you want a huge challenge. Software should not be designed this was in 2021!

I'm migrating the code to Clean Acrutature so everything should have its own service class exposed by an interface. Done 5k lines 95k more to go

@kastroph kastroph closed this as completed Nov 6, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
tenet-performance Performance related issue
Projects
None yet
Development

No branches or pull requests

3 participants