search

dotnet / BenchmarkDotNet

Powerful .NET library for benchmarking
https://benchmarkdotnet.org
MIT License
10.59k stars 970 forks source link

Unable to get `-p ETW` working these days #2537

Closed AndyAyersMS closed 8 months ago

AndyAyersMS commented 8 months ago

This could be a me problem, but -p ETW stopped working for me recently and I don't know why.

Symptom is

dotnet.exe "run" "-c" "Release" "-f" "net8.0" "--" "--filter" "System.Collections.CtorFromCollection<Int32>.ConcurrentStack?Size: 512?" "--corerun" "C:\repos\runtime0\artifacts\tests\coreclr\windows.x64.Release\Tests\Core_Root\corerun.exe" "--profiler" "ETW"

... snip ...

// **************************
// Benchmark: CtorFromCollection<Int32>.ConcurrentStack: Job-ZHSTRJ(PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [Size=512]
// *** Execute ***
// Launch: 1 / 1
// Execute: C:\repos\runtime0\artifacts\tests\coreclr\windows.x64.Release\Tests\dc4fea58-2544-45a1-b59c-832a2b0ac24f\corerun.exe 2904fe10-5e27-41bb-8d4b-e6386be17742.dll --anonymousPipes 2712 2720 --benchmarkName "System.Collections.CtorFromCollection<Int32>.ConcurrentStack(Size: 512)" --job "PowerPlanMode=00000000-0000-0000-0000-000000000000, Toolchain=CoreRun, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1" --benchmarkId 0 in C:\repos\performance\artifacts\bin\MicroBenchmarks\Release\net8.0\2904fe10-5e27-41bb-8d4b-e6386be17742\bin\Release\net8.0\publish

STDERR:
Unhandled exception. System.Runtime.InteropServices.COMException (0x800700AA): The requested resource is in use. (0x800700AA)
   at System.Runtime.InteropServices.Marshal.ThrowExceptionForHR(Int32 errorCode)
   at Microsoft.Diagnostics.Tracing.Session.TraceEventSession.EnableKernelProvider(Keywords flags, Keywords stackCapture)
   at BenchmarkDotNet.Diagnostics.Windows.KernelSession.EnableProviders()
   at BenchmarkDotNet.Diagnostics.Windows.EtwProfiler.Start(DiagnoserActionParameters parameters)
   at BenchmarkDotNet.Diagnostics.Windows.EtwProfiler.Handle(HostSignal signal, DiagnoserActionParameters parameters)

Roughly speaking windows seems to be saying the kernel session is in use already. I can't be sure; trying to stop it doesn't work either

xperf -stop
xperf: error: NT Kernel Logger: The instance name passed was not recognized as valid by a WMI data provider. (0x1069).

I thought it might be related to ancient WPT tools so I updated those to latest, and that worked for exactly one run before failing again the same way.

Thought I'd post this here in case anyone else has or is running into this problem.

AndyAyersMS commented 8 months ago

@adamsitnik @brianrob FYI

AndyAyersMS commented 8 months ago

Possibly relevant, my event log for Kernel-EventTracing is full of entries like

Session "SensorFramework-{92410660-c9bb-97e0-8602-f3e902e2933e}" failed to start with the following error: 0xC0000035
adamsitnik commented 8 months ago

Hello @AndyAyersMS

I've tried to repro and it work fine for me:

git checkout main && git pull --rebase && git fetch upstream && git merge upstream/main && git push
dotnet run "-c" "Release" "-f" "net8.0" "--" "--filter" "System.Collections.CtorFromCollection<Int32>.ConcurrentStack?Size: 512?" "--profiler" "ETW"
BenchmarkDotNet v0.13.13-nightly.20240228.135, Windows 11 (10.0.22631.3155/23H2/2023Update/SunValley3)
AMD Ryzen Threadripper PRO 3945WX 12-Cores, 1 CPU, 24 logical and 12 physical cores
.NET SDK 9.0.100-alpha.1.23531.2
  [Host]     : .NET 8.0.2 (8.0.224.6711), X64 RyuJIT AVX2
  Job-YTZCRE : .NET 8.0.2 (8.0.224.6711), X64 RyuJIT AVX2

PowerPlanMode=00000000-0000-0000-0000-000000000000  IterationTime=250.0000 ms  MaxIterationCount=20
MinIterationCount=15  WarmupCount=1

| Method          | Size | Mean     | Error     | StdDev    | Median   | Min      | Max      | Gen0   | Gen1   | Allocated |
|---------------- |----- |---------:|----------:|----------:|---------:|---------:|---------:|-------:|-------:|----------:|
| ConcurrentStack | 512  | 2.694 us | 0.0176 us | 0.0165 us | 2.692 us | 2.673 us | 2.726 us | 1.9555 | 0.1074 |  16.05 KB |

// * Legends *
  Size      : Value of the 'Size' parameter
  Mean      : Arithmetic mean of all measurements
  Error     : Half of 99.9% confidence interval
  StdDev    : Standard deviation of all measurements
  Median    : Value separating the higher half of all measurements (50th percentile)
  Min       : Minimum
  Max       : Maximum
  Gen0      : GC Generation 0 collects per 1000 operations
  Gen1      : GC Generation 1 collects per 1000 operations
  Allocated : Allocated memory per single operation (managed only, inclusive, 1KB = 1024B)
  1 us      : 1 Microsecond (0.000001 sec)

// * Diagnostic Output - MemoryDiagnoser *

// * Diagnostic Output - EtwProfiler *
Exported 1 trace file(s). Example:
D:\projects\performance\artifacts\bin\MicroBenchmarks\Release\net8.0\BenchmarkDotNet.Artifacts\System.Collections.CtorFromCollection_Int32_.ConcurrentStack(Size_ 512)-20240304-095334.etl

Could you please try to use PerfView to start a profiling session and see if it works? If it does not, the Log (right bottom corner) might help us to get more info.

AndyAyersMS commented 8 months ago

This started working again after a git clean -dfx in the dotnet/performance repo. Not sure why.

AndyAyersMS commented 4 months ago

This is happening again. Wonder if it's the same issue as in https://github.com/microsoft/perfview/issues/1723

adamsitnik commented 4 months ago

Wonder if it's the same issue as in

I have no idea. But from BDN perspective we have not changed anything in the code that launches the ETW sessions for almost 2 years now: https://github.com/dotnet/BenchmarkDotNet/blob/01d9b7889e13cf756068985275a3997217e4a102/src/BenchmarkDotNet.Diagnostics.Windows/Sessions.cs#L57