How to: Diagnose UI delays caused by extensions

Applies to: Visual Studio Visual Studio for Mac

When UI becomes unresponsive, Visual Studio examines the call-stack of the UI thread, starting with the leaf and working towards the base. If Visual Studio determines that a call-stack frame belongs to a module that is part of an installed and enabled extension, it shows a notification.

The notification informs the user that the UI delay (that is, the unresponsiveness in the UI) might have been the result of code from an extension. It also provides the user with options to disable the extension or future notifications for that extension.

This document describes how you can diagnose what in your extension code is causing UI delay notifications.

An overview of the diagnostic process is as follows:

1. Identify the trigger scenario.
2. Restart VS with activity logging on.
3. Start ETW tracing.
4. Trigger the notification to appear again.
5. Stop ETW tracing.
6. Examine the activity log to get the delay ID.
7. Analyze the ETW trace using delay ID from step 6.

In the following sections, we will go through these steps in more detail.

Identify the trigger scenario

To do diagnose a UI delay, you first need to identify what (sequence of actions) causes Visual Studio to show the notification. This is in order for you to able to trigger the notification later with logging turned on.

Restart VS with activity logging on

Visual Studio can generate an "activity log" that provides information helpful when debugging an issue. To turn on activity logging in Visual Studio, open Visual Studio with the /log command line option. After Visual Studio starts, the activity log is stored in the following location:

%APPDATA%\Microsoft\VisualStudio\<vs_instance_id>\ActivityLog.xml

To learn more about how you can find your VS instance ID, see Tools for detecting and managing Visual Studio instances. We will use this activity log later to find out more information about UI delays and related notifications.

Starting ETW tracing

You can use PerfView to collect an ETW trace. PerfView provides an easy-to-use interface both for collecting an ETW trace and for analyzing it. Use the following command to collect a trace:

Perfview.exe collect C:\trace.etl /BufferSizeMB=1024 -CircularMB:2048 -Merge:true -Providers:*Microsoft-VisualStudio:@StacksEnabled=true -NoV2Rundown /kernelEvents=default+FileIOInit+ContextSwitch+Dispatcher

This enables the "Microsoft-VisualStudio" provider, which is the provider Visual Studio uses for events related to UI delay notifications. It also specifies the keyword for the kernel provider that PerfView can use to generate the Thread Time Stacks view.

Trigger the notification to appear again

Once PerfView has started trace collection, you can use the trigger action sequence (from step 1) for the notification to appear again. Once the notification is shown, you can stop trace collection for PerfView to process and generate the output trace file.

Stop ETW tracing

To stop trace collection, simply use the Stop collection button on the PerfView window. After you stop trace collection, PerfView will automatically process the ETW events and generates an output trace file.

Examine the activity log to get the delay ID

As mentioned earlier, you can find the activity log at %APPDATA%\Microsoft\VisualStudio<vs_instance_id>\ActivityLog.xml. Every time Visual Studio detects an extension UI delay, it writes a node to the activity log with UIDelayNotifications as the source. This node contains four pieces of information about the UI delay:

• The UI delay ID, a sequential number that uniquely identifies a UI delay in a VS session
• The session ID, which uniquely identifies your Visual Studio session from start to close
• Whether or not a notification was shown for the UI delay
• The extension that likely caused the UI delay

<entry>
  <record>271</record>
  <time>2018/02/03 12:02:52.867</time>
  <type>Information</type>
  <source>UIDelayNotifications</source>
  <description>A UI delay (Delay ID = 0) has been detected. (Session ID=16e49d4b-26c2-4247-ad1c-488edeb185e0; Blamed extension="UIDelayR2"; Notification shown? Yes.)</description>
</entry>

After you find the correct UI delay in the activity log, write down the UI delay ID specified in the node. You'll use the ID to look for the corresponding ETW event in the next step.

Analyze the ETW trace

Next, open the trace file. You can do this either using the same instance of PerfView or by starting a new instance and setting the current folder path in the top-left of the window to the location of the trace file.

Then, select the trace file in the left pane and open it by choosing Open from the right-click or context menu.

It can take several minutes for PerfView to process and open the trace. Once the trace is open, a list of various "views" appear under it.

We will first use the Events view to obtain the time-range of the UI delay:

1. Open the Events view by selecting Events node under the trace and choosing Open from the right-click or context menu.
2. Select "Microsoft-VisualStudio/ExtensionUIUnresponsiveness" in the left pane.
3. Press Enter

The selection is applied and all ExtensionUIUnresponsiveness events are displayed in the right pane.

Each row in the right pane corresponds to a UI delay. The event includes a "Delay ID" value which should match the delay ID in the activity log from the step 6. Since ExtensionUIUnresponsiveness is fired at the end of the UI delay, the timestamp of the event (roughly) marks the end time of the UI delay. The event also contains the duration of the delay. We can subtract the duration from the end timestamp to obtain the timestamp of when the UI delay started.

In the previous screenshot, for example, the timestamp of the event is 12,125.679 and the delay duration is 6,143.085 (ms). Thus,

• The delay start is 12,125.679 - 6,143.085 = 5,982.594.
• The UI delay time range is 5,982.594 to 12,125.679.

Once we have the time range, we can close out of the Events view and open the Thread Time (with StartStop Activities) Stacks view. This view is especially handy because often extensions that are blocking the UI thread are merely waiting on other threads or an I/O-bound operation. Thus, the CPU Stack view, which is the go-to option for most cases, may not capture the time the thread spends blocking since it is not using the CPU during that time. The Thread Time Stacks solves this problem by properly showing blocked time.

While opening Thread Time Stacks view, choose the devenv process to start analysis.

In the Thread Time Stacks view, in the top-left of the page, you can set the time-range to the values we calculated in the previous step and press Enter so the stacks are adjusted to that time range.

You can also further filter this view by only including stacks that contain modules from your package.

• Set GroupPats to empty text to remove any grouping added by default.
• Set IncPats to include part of your assembly name in addition to existing process filter. In this case, it should be devenv;UIDelayR2.

PerfView has detailed guidance under the Help menu that you can use to identify performance bottlenecks in your code. Additionally, the following links provide more information on how to utilize Visual Studio threading APIs to optimize your code:

• https://github.com/Microsoft/vs-threading/blob/master/doc/index.md
• https://github.com/Microsoft/vs-threading/blob/master/doc/cookbook_vs.md

You can also use the new Visual Studio static analyzers for extensions (NuGet package here), that provide guidance on best practices for writing efficient extensions. See a list of VS SDK analyzers and threading analyzers.