Enabling a CPU profiler on Windows automatically enables ETW tracing and slows the app down by over 100x

[romkatv]

Description

When using Visual Studio 2022 on Windows to profile CPU Usage of a dotnet application, the application can run over 100 times slower and produce a CPU profile that is heavily dominated by instrumentation code.

Reproduction Steps

1. Create CpuProfilerTest.csproj with the following content:

   <Project Sdk="Microsoft.NET.Sdk">
     <PropertyGroup>
       <OutputType>Exe</OutputType>
       <TargetFramework>net7.0</TargetFramework>
     </PropertyGroup>
   </Project>

2. Create CpuProfilerTest.cs with the following content:

   using System;
   using System.Diagnostics;
   using System.Threading;
   using System.Threading.Tasks;
   
   while (true) {
     const int N = 100000;
     Stopwatch watch = Stopwatch.StartNew();
     for (int i = 0; i != N; ++i) {
       Task t = new(delegate { });
       t.RunSynchronously();
       t.Wait();
     }
     Console.WriteLine("took {0:N2}ms", watch.Elapsed.TotalMilliseconds);
     Thread.Sleep(TimeSpan.FromSeconds(1));
   }

3. Open CpuProfilerTest.csproj in Microsoft Visual Studio Community 2022 (64-bit) 17.4.4 on Windows 10.
4. Switch to Release in the Solution Configurations dropdown at the top.
   
5. Press Ctrl+F5 or click Debug → Start Without Debugging.
6. Wait for a few seconds. Observe console output similar to the following:

   took 15.52ms
   took 9.17ms
   took 7.96ms
   took 8.26ms
   took 8.06ms
   took 8.34ms
   

7. Press Ctrl+C to terminate the console application.
8. Press Alt+F2 or click Debug → Performance Profiler....
9. Check CPU Usage and make sure that everything else is unchecked.
   
10. Click on the gear icon next to CPU Usage to open its settings and make sure that Collect call counters (.NET Only) is unset and Select CPU sample rate is set to Default (1000 samples / second).
    
11. Click Start.
    
12. Wait for a few seconds. Observe console output similar to the following:

    took 1,105.79ms
    took 1,064.50ms
    took 1,061.24ms
    took 1,067.87ms
    took 1,069.18ms
    took 1,063.62ms
    

    Note that it now takes over 100 times longer for the application to do the same amount of work.
13. Press Ctrl+C to terminate the console application.
14. Wait for Visual Studio to process the profile and observe something similar to this:
    
    Note that 93% of CPU time is spent in System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore.

Expected behavior

Given that without a CPU profiler it takes the application around 8ms to do the work, I expect that with the CPU profiler it won't take more than 10ms.

I also expect that the CPU profile presented by Visual Studio closely resembles the actual CPU profile of the application when it runs without being profiled.

Actual behavior

The actual behavior is described in Reproduction Steps.

Regression?

No response

Known Workarounds

I'd love to know a workaround if there is one.

My goal is to get a CPU profile of my application. The application reads many small messages from WebSocket, which implies a lot of Task objects. If I use the CPU profiler from Visual Studio, the application slows down to such a great extent that the profile is no longer relevant.

I've tried ticking Instrumentation instead of CPU Usage.

This incurs about 4x slowdown (much better than 100x but still fairly high). More importantly, it measures wall time instead of CPU time, so the profile is dominated by various sleep and wait functions.

I've tried disabling ETW tracing by setting COMPlus_ETWEnabled=0 environment variable. This made no difference. I've also tried using the following App.config:

<?xml version="1.0"?>
<configuration>
  <runtime>
    <etwEnable enabled="false" />
  </runtime>
</configuration>

This also made no difference.

I'm open to using a different tool (instead of Visual Studio) to generate/analyze a CPU profile. Any suggestions would be helpful.

Configuration

• Microsoft Visual Studio Community 2022 (64-bit) - Version 17.4.4
• Microsoft Windows 10 Pro, Version 10.0.19045
• TargetFramework net7.0.

Other information

I'm not sure if I'm filing this issue against the correct component. My apologies if this is a wrong channel.

[ghost]

Tagging subscribers to this area: @tommcdon
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

When using Visual Studio 2022 on Windows to profile CPU Usage of a dotnet application, the application can run over 100 times slower and produce a CPU profile that is heavily dominated by instrumentation code.

Reproduction Steps

1. Create CpuProfilerTest.csproj with the following content:

   <Project Sdk="Microsoft.NET.Sdk">
     <PropertyGroup>
       <OutputType>Exe</OutputType>
       <TargetFramework>net7.0</TargetFramework>
     </PropertyGroup>
   </Project>

2. Create CpuProfilerTest.cs with the following content:

   using System;
   using System.Diagnostics;
   using System.Threading;
   using System.Threading.Tasks;
   
   while (true) {
     const int N = 100000;
     Stopwatch watch = Stopwatch.StartNew();
     for (int i = 0; i != N; ++i) {
       Task t = new(delegate { });
       t.RunSynchronously();
       t.Wait();
     }
     Console.WriteLine("took {0:N2}ms", watch.Elapsed.TotalMilliseconds);
     Thread.Sleep(TimeSpan.FromSeconds(1));
   }

3. Open CpuProfilerTest.csproj in Microsoft Visual Studio Community 2022 (64-bit) 17.4.4 on Windows 10.
4. Switch to Release in the Solution Configurations dropdown at the top.
   
5. Press Ctrl+F5 or click Debug → Start Without Debugging.
6. Wait for a few seconds. Observe console output similar to the following:

   took 15.52ms
   took 9.17ms
   took 7.96ms
   took 8.26ms
   took 8.06ms
   took 8.34ms
   

7. Press Ctrl+C to terminate the console application.
8. Press Alt+F2 or click Debug → Performance Profiler....
9. Check CPU Usage and make sure that everything else is unchecked.
   
10. Click on the gear icon next to CPU Usage to open its settings and make sure that Collect call counters (.NET Only) is unset and Select CPU sample rate is set to Default (1000 samples / second).
    
11. Click Start.
    
12. Wait for a few seconds. Observe console output similar to the following:

    took 1,105.79ms
    took 1,064.50ms
    took 1,061.24ms
    took 1,067.87ms
    took 1,069.18ms
    took 1,063.62ms
    

    Note that it now takes over 100 times longer for the application to do the same amount of work.
13. Press Ctrl+C to terminate the console application.
14. Wait for Visual Studio to process the profile and observe something similar to this:
    
    Note that 93% of CPU time is spent in System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore.

Expected behavior

Given that without a CPU profiler it takes the application around 8ms to do the work, I expect that with the CPU profiler it won't take more than 10ms.

I also expect that the CPU profile presented by Visual Studio closely resembles the actual CPU profile of the application when it runs without being profiled.

Actual behavior

The actual behavior is described in Reproduction Steps.

Regression?

No response

Known Workarounds

I'd love to know a workaround if there is one.

My goal is to get a CPU profile of my application. The application reads many small messages from WebSocket, which implies a lot of Task objects. If I use the CPU profiler from Visual Studio, the application slows down to such a great extent that the profile is no longer relevant.

I've tried ticking Instrumentation instead of CPU Usage.

This incurs about 4x slowdown (much better than 100x but still fairly high). More importantly, it measures wall time instead of CPU time, so the profile is dominated by various sleep and wait functions.

I've tried disabling EWT tracing by setting COMPlus_ETWEnabled=0 environment variable. This made no difference. I've also tried using the following App.config:

<?xml version="1.0"?>
<configuration>
  <runtime>
    <etwEnable enabled="false" />
  </runtime>
</configuration>

This also made no difference.

I'm open to using a different tool (instead of Visual Studio) to generate/analyze a CPU profile. Any suggestions would be helpful.

Configuration

• Microsoft Visual Studio Community 2022 (64-bit) - Version 17.4.4
• Microsoft Windows 10 Pro, Version 10.0.19045
• TargetFramework net7.0.

Other information

I'm not sure if I'm filing this issue against the correct component. My apologies if this is a wrong channel.

Author:	romkatv
Assignees:	-
Labels:	area-Diagnostics-coreclr
Milestone:	-

[stephentoub]

cc: @karpinsn, @brianrob

[romkatv]

I came up with a workaround. I added the following statement at the very beginning of my application:

typeof(System.Diagnostics.Tracing.EventSource)
    .GetField("m_eventSourceEnabled", BindingFlags.Instance | BindingFlags.NonPublic)
    .SetValue(Type.GetType("System.Threading.Tasks.TplEventSource")
                  .GetField("Log", BindingFlags.Static | BindingFlags.Public)
                  .GetValue(null),
              false);

This sets System.Threading.Tasks.TplEventSource.Log.m_eventSourceEnabled to false. Normally this field is already false but when the application is started by the CPU profiler it is set to true. By reverting it back to false we disable the costly and unwanted ETW event tracing and get a representative CPU profile without slowing down the application.

This won't help when attaching a CPU profiler to a running process. This can be worked around by starting a thread within the application to periodically set TplEventSource.Log.m_eventSourceEnabled to false.

[tommcdon]

@davmason

[brianrob]

@romkatv, your workaround tells us exactly what this is. The verbosity of the TPL events is super high in apps that use lots of async/await or Tasks. @karpinsn, do you expect the TPL events to be on?

[karpinsn]

@brianrob I thought we disabled TPL for all scenarios but it looks like we still have them enabled in the CPU Usage tool in the Profiler scenario, they are just disabled during the debugging scenario. I'll follow up with Evan, I think we should turn them off in the profiler as well (I thought we had).

@romkatv we have a registry key that you can set to disable these events. Running the following from a command line will disable the TPL events in the profiler and should workaround your issue without the need for the code change:
reg add HKEY_LOCAL_MACHINE\Software\Microsoft\VisualStudio\DiagnosticsHub /v CpuTool.DisableTplEventCollection /t REG_DWORD /d 1 /reg:32

[romkatv]

@brianrob I thought we disabled TPL for all scenarios but it looks like we still have them enabled in the CPU Usage tool in the Profiler scenario, they are just disabled during the debugging scenario.

TPL logging is enabled when debugging (F5). My workaround incidentally solved the long-standing performance issue I had with debugging my project.

@romkatv we have a registry key that you can set to disable these events. Running the following from a command line will disable the TPL events in the profiler and should workaround your issue without the need for the code change: reg add HKEY_LOCAL_MACHINE\Software\Microsoft\VisualStudio\DiagnosticsHub /v CpuTool.DisableTplEventCollection /t REG_DWORD /d 1 /reg:32

Thanks!

Is there documentation for this switch somewhere? If not, a reference to the code would suffice.

[karpinsn]

TPL logging is enabled when debugging (F5). My workaround incidentally solved the long-standing performance issue I had with debugging my project.

Turns out the debugger is getting the TPL events to stitch async tasks together for the Parallel Stacks view. I'll follow up with them and see if there is anything we can do.

Is there documentation for this switch somewhere? If not, a reference to the code would suffice.

Nope, this is really just an internal switch that we use for our own testing and lives inside the Visual Studio code base. I'm going to see if we can just expose this as a setting in the CPU Usage settings (gear icon) so users can optionally enable/disable it.

[hoyosjs]

Marking as future since this is not tracked by work in the runtime, but rather VS work.