拡張機能によって発生する UI の遅延を診断する

UI が応答しなくなると、Visual Studio では UI スレッドの呼び出し履歴が調べられ、リーフから始まり、ベースに向かって動作します。 Visual Studio によって、呼び出し履歴フレームが、インストールされ有効な拡張機能の一部であるモジュールに属していると判断されると、通知が表示されます。

通知は、UI の遅延 (つまり、UI の応答不能) が拡張機能からのコードの結果である可能性があることをユーザーに通知します。 また、拡張機能またはその拡張機能の今後の通知を無効にするオプションもユーザーに提供されます。

このドキュメントでは、UI 遅延通知の原因となっている拡張機能コードを診断する方法について説明します。

診断プロセスの概要は次のとおりです。

1. トリガー シナリオを特定します。
2. アクティビティのログ記録をオンにして VS を再起動します。
3. ETW トレースを開始します。
4. 通知が再び表示されるようにトリガーします。
5. ETW トレースを停止します。
6. アクティビティ ログを調べて、遅延 ID を取得します。
7. 手順 6 の遅延 ID を使用して ETW トレースを分析します。

以降のセクションでは、これらの手順について詳しく説明します。

トリガー シナリオを特定する

UI の遅延を診断するには、まず、Visual Studio で通知が表示される原因 (一連のアクション) を特定する必要があります。 これは、ログ記録を有効にして後で通知をトリガーできるようにするためです。

アクティビティのログ記録をオンにして VS を再起動する

Visual Studio では、問題のデバッグ時に役立つ情報を提供する "アクティビティ ログ" を生成できます。 Visual Studio でアクティビティ ログを有効にするには、/log コマンド ライン オプションを使用して Visual Studio を開きます。 Visual Studio の起動後、アクティビティ ログは次の場所に格納されます。

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

VS インスタンス ID を検索する方法の詳細については、「 Visual Studio インスタンスを検出して管理するためのツール」を参照してください。 このアクティビティ ログは、後で UI の遅延と関連する通知に関する詳細情報を確認するために使用します。

ETW トレースを開始しています

PerfView を使用して、ETW トレースを収集できます。 PerfView は、ETW トレースの収集と分析の両方に使いやすいインターフェイスを提供します。 トレースを収集するには、次のコマンドを使用します。

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

これにより、"Microsoft-VisualStudio" プロバイダーが有効になります。これは、Visual Studio が UI 遅延通知に関連するイベントに使用するプロバイダーです。 また、PerfView が スレッド タイム スタック ビューの生成に使用できるカーネル プロバイダーのキーワードも指定します。

通知が再び表示されるようにトリガーする

PerfView がトレース収集を開始したら、トリガー アクション シーケンス (手順 1) を使用して通知を再び表示できます。 通知が表示されたら、PerfView のトレース収集を停止して、出力トレース ファイルを処理および生成できます。

ETW トレースを停止する

トレース コレクションを停止するには、PerfView ウィンドウの [コレクションの停止 ] ボタンを使用します。 トレース収集を停止すると、PerfView によって ETW イベントが自動的に処理され、出力トレース ファイルが生成されます。

アクティビティ ログを調べて遅延 ID を取得する

前述のように、アクティビティ ログは %APPDATA%\Microsoft\VisualStudio<vs_instance_id>\ActivityLog.xmlにあります。 Visual Studio は、拡張機能 UI の遅延を検出するたびに、ソースとして UIDelayNotifications を使用してノードをアクティビティ ログに書き込みます。 このノードには、UI の遅延に関する 4 つの情報が含まれています。

• UI 遅延 ID。VS セッションの UI 遅延を一意に識別するシーケンシャル番号。
• セッション ID。Visual Studio セッションを最初から最後まで一意に識別します。
• UI の遅延に関する通知が表示されたかどうか
• UI の遅延を引き起こした可能性のある拡張機能

<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>

アクティビティ ログに正しい UI 遅延が見つかると、ノードで指定された UI 遅延 ID を書き留めます。 ID を使用して、次の手順で対応する ETW イベントを検索します。

ETW トレースを分析する

次に、トレース ファイルを開きます。 これを行うには、PerfView の同じインスタンスを使用するか、新しいインスタンスを開始し、ウィンドウの左上にある現在のフォルダー パスをトレース ファイルの場所に設定します。

次に、左側のウィンドウでトレース ファイルを選択し、右クリックまたはコンテキスト メニューから [開く ] を選択して開きます。

PerfView がトレースを処理して開くには、数分かかる場合があります。 トレースが開くと、その下にさまざまな "ビュー" の一覧が表示されます。

まず、[ イベント ] ビューを使用して、UI 遅延の時間範囲を取得します。

1. [ イベント ] ビューを開くには、トレース Events ノードを選択し、右クリックまたはコンテキスト メニューから [開く ] を選択します。
2. 左側のウィンドウで "Microsoft-VisualStudio/ExtensionUIUnresponsiveness" を選択します。
3. Enter キーを押す

選択が適用され、すべての ExtensionUIUnresponsiveness イベントが右側のウィンドウに表示されます。

右側のウィンドウの各行は、UI の遅延に対応します。 このイベントには、ステップ 6 のアクティビティ ログの遅延 ID と一致する必要がある "Delay ID" 値が含まれています。 ExtensionUIUnresponsiveness は UI 遅延の終了時に発生するため、イベントのタイムスタンプ (おおよそ) は UI 遅延の終了時刻を示します。 このイベントには、遅延の期間も含まれます。 終了タイムスタンプから期間を減算して、UI 遅延が開始されたときのタイムスタンプを取得できます。

たとえば、前のスクリーンショットでは、イベントのタイムスタンプは 12,125.679 で、遅延時間は 6,143.085 (ミリ秒) です。 したがって

• 遅延開始は 12,125.679 - 6,143.085 = 5,982.594 です。
• UI 遅延時間の範囲は 5,982.594 から 12,125.679 です。

時間範囲を取得したら、[ イベント ] ビューを閉じて、[ スレッド時間] (StartStop アクティビティを含む) スタック ビューを 開くことができます。 このビューは特に便利です。UI スレッドをブロックしている拡張機能は、他のスレッドまたは I/O バインド操作を待機しているだけであることがよくあります。 したがって、ほとんどの場合、go-to オプションである CPU スタック ビューでは、その間に CPU を使用していないため、スレッドがブロックに費やす時間がキャプチャされない可能性があります。 スレッド タイム スタックは、ブロックされた時間を正しく表示することで、この問題を解決します。

スレッド タイム スタック ビューを開いている間に、分析を開始する devenv プロセスを選択します。

[スレッド時間スタック] ビューのページの左上で、時間範囲を前の手順で計算した値に設定し、Enter キーを押して、スタックがその時間範囲に調整されるようにすることができます。

パッケージのモジュールを含むスタックのみを含めることで、このビューをさらにフィルター処理することもできます。

• GroupPats を空のテキストに設定して、既定で追加されたグループを削除します。
• 既存のプロセス フィルターに加えてアセンブリ名の一部を含むように IncPats を設定します。 この場合は、 devenv にする必要があります。UIDelayR2。

PerfView には、コード内のパフォーマンスのボトルネックを特定するために使用できる ヘルプ メニューの詳細なガイダンスがあります。 さらに、Visual Studio スレッド API を使用してコードを最適化する方法の詳細については、次のリンクを参照してください。

• https://github.com/microsoft/vs-threading/blob/main/docfx/index.md
• https://github.com/microsoft/vs-threading/blob/main/docfx/docs/cookbook_vs.md

また、拡張機能用の新しい Visual Studio 静的アナライザー ( ここでは NuGet パッケージ) を使用して、効率的な拡張機能を記述するためのベスト プラクティスに関するガイダンスを提供することもできます。 VSSDK アナライザーとスレッド アナライザーの一覧を参照してください。