UI フリーズの原因を見つける

サンプルアプリケーション

サンプルアプリケーションは、テキストファイルの行を逆にするために使用されます（例: ABC => CBA）。ファイルの選択ボタンを使用して、ユーザーは処理する 1 つ以上のテキストファイルを選択します。プロセスファイルボタンは、ファイル内の行を逆にする別の BackgroundWorker スレッドを実行します。ウィンドウの左隅に進行状況が表示されます。処理が終了すると、ラベルはすべてのファイルが正常に処理されましたを報告します。

ソースコードは github(英語) で入手できます。

このアプリケーションには重大な欠点があります。ファイル処理を開始した後、処理が終了するまで UI ラグが発生します。

タイムラインプロファイリングを使用して、これらのフリーズが発生する理由を調べましょう ! *

プロファイラの実行とスナップショットの取得

1. Visual Studio で MassFileProcessing.sln ソリューションを開きます。

2. ReSharper | プロファイル | スタートアップ設定のパフォーマンスプロファイリングを実行しています ... を選択してプロファイラを実行します。

3. プロファイリングタイプでは、タイムラインを選択します。

   

4. 実行をクリックします。dotTrace はアプリケーションを実行し、プロファイリングプロセスを制御するための特別なコントローラーウィンドウを表示します。

   

   私たちのアプリでパフォーマンスの問題を再現しようとしましょう。

5. ファイルの選択をクリックして、アプリケーションに付属の 5 つのテキストファイルをテキストファイルフォルダーに選択します。

   

6. ファイル処理を開始するには、プロセスファイルをクリックします。ご覧のように、アプリケーションは非常に悪いです。実際には、ファイル処理が完了してすべてのファイルが正常に処理されましたが表示されるまで、ファイル処理の進行状況を見ることさえできません。

7. コントローラーウィンドウでスナップショットを取得して待機するをクリックして、タイムラインプロファイリングスナップショットを収集します。スナップショットは Visual Studio の別のパフォーマンスプロファイラツールウィンドウで開きます。

8. アプリケーションを閉じます。これにより、コントローラーウィンドウも閉じます。

タイムラインプロファイリングスナップショットの分析

1. スレッドをクリックしてスレッドツールウィンドウを開きます。既定では、アンマネージスレッドを除くすべてのアプリケーションスレッドが表示されます。* 表示されるすべてのフィルター値は、現在表示されているすべてのスレッドについて計算されます。さらに分析するために、作業をしないスレッドには興味がありません。まず取り除きましょう。

   

2. ツールウィンドウのスレッドのリストを参照してください。メインアプリケーションスレッド、実行時にオブジェクトをファイナライズするために使用するファイナライザスレッド（アプリケーションでは機能しません）、およびガーベッジコレクションスレッド（バックグラウンド GC の実行に使用）が含まれています。バックグラウンドスレッドは CLR スレッドプールによって作成されるため、アプリケーションのファイルを処理する BackgroundWorker スレッドはスレッドプール（ID 13456）と識別されます。もう 1 つのスレッドプール（ID 7416）も動作しません。これは、おそらく補助 CLR スレッドプールです。私たちの分析と無関係なファイナライザとスレッドプール（ID 7416）スレッドを隠してみましょう。

3. スレッドツールウィンドウで、ファイナライザとスレッドプール（ID 7416）スレッドを選択します。

4. 右クリックし、選択したスレッドを非表示にするを選択します。

   

5. スレッドウィンドウを参照してください。現在、スナップショットデータには次のフィルターが適用されています: 「非表示のスレッドを除くすべてのスレッドの有効期間間隔を選択する」。

   

   他のフィルターのデータがどのように影響を受けたかに注意してください。例: スレッドの状態の状態時間は、現在隠れているものを除くすべてのスレッドについて計算されます。ホットスポットと呼び出しツリーも変更され、フィルタリングされたスレッドからの呼び出しのみが表示されます。

6. スレッドダイアグラムの現在のスケールでは、13456 スレッドプール (BackgroundWorker スレッド) を詳細に見ることができません。ダイアグラム全体に収まるようにズームインしてみましょう。これを行うには、スレッドダイアグラム * で Mouse Wheel を使用します。これにより、表示可能な時間範囲によるフィルター 1489 ミリ秒が自動的に追加されます。このフィルターが他のフィルターにどのように影響するかに注意してください。表示可能な時間範囲のすべての値が再計算されます。これで、次のフィルターがスナップショットデータに適用されます: 「非表示のスレッドを除くすべてのスレッドの表示可能な時間範囲内のすべての時間間隔を選択する」。

   

7. スレッドダイアグラムを参照してください。スレッドの状態が時間の経過とともにどのように変化したかがわかります。例: BackgroundWorker スレッド 13456 スレッドプールは、約 16 秒後 ( プロセスファイルボタンをクリックした後) に開始されました。ほとんどの時間、スレッドは実行 (濃い青の間隔) でした。さらに、スレッドが待機状態 (薄い青の間隔) だった間隔もあります。

8. スレッドツールウィンドウ * のプロセス概要ダイアグラムを参照してください。CPU の利用に加えて、パフォーマンス分析に非常に役立つ 2 つのイベントダイアグラムを示しています。UI フリーズバーは、13456 スレッドプールが作成された直後にフリーズが開始されたことを示します。

   ガベージコレクションのブロック GC もこの時間間隔で集中的に実行されました。ブロッキング GC はすべての管理対象スレッドを中断させるため、UI がフリーズする可能性があります。

   これらの出来事を詳しく見なければならない。

   

9. まず、表示されている時間範囲フィルターが不要になったため削除しましょう。これを行うには、スレッドツールウィンドウの上部にあるフィルターをクリックします *. ダイアグラムが再びズームアウトされます。

   

10. 次に、UI のフリーズイベントをより詳細に調べてみましょう。このようなフリーズの主な原因は何ですか？ これらは:

    • 長いまたは頻繁なブロッキング GC;

    • 他のスレッド（たとえば、ロックの競合による）による UI スレッドのブロック。

    • および / または過剰な計算作業を UI スレッド上で行うことができます。

    真の犯人だけが残るまで、これらの原因を一つずつ除外します。

11. スレッドツールウィンドウのプロセス概要セクションで対応するバーをクリックして、UI フリーズイベントを選択します。これにより、UI フリーズイベントによるフィルターが適用されます。フリーズ時間範囲によるフィルターだけでなく、メインスレッドによるフィルターも適用されることに注意してください。メインスレッドはアプリケーションで UI 操作を処理する唯一のスレッドであるため、後者は自動的に実行されます。結果として得られるフィルターは、「UI フリーズイベントが発生したメインスレッドのすべての時間間隔を選択する」になります。

    

12. このフリーズの真の原因を特定するために、他のフィルター値を調べてみましょう。解析すべき最初の潜在的な原因は、過剰なブロッキング GC です。

    ブロッキング GC をクリックしてブロッキング GC フィルターを開き、値を確認します。

    現在適用されているフィルターを考慮すると、メインスレッドがフリーズ中に GC によってブロックされた時間（ブロッキング GC 値）と（ブロッキング GC を除外する値）は示されませんでした。

    

    ブロッキング GC 時間は非常に長く（420 ミリ秒、または選択した間隔の 10.2%）、パフォーマンスに多少の影響を与える可能性があります。それにもかかわらず、4 秒の凍結の原因となることはほとんどありません。容疑者リストから過度のガベージコレクションを除外することがあります。

13. ブロッキング GC を除外する値をクリックします。結果のフィルターは、「UI フリーズイベントが発生し、ブロッキング GC が実行されていないメインスレッド上のすべての時間間隔を選択する」になります。

14. 潜在的な原因を調査しましょう。「他のスレッドによるブロック」と「メインスレッドでの過度の作業」

    スレッドの状態の値を開いて参照してください。このフィルターは、特定の状態でスレッドが費やした合計時間を示します。現在適用されているフィルターを考慮すると、フリーズ中の Main スレッドの状態を示します。

    

    フリーズ時間（92.9%、または 3426 ミリ秒）のほとんどは、スレッドが実行のようにいくつかの作業を行っていたようです。待機状態の 225 ミリ秒値が小さすぎるため、自動的に「他のスレッドによるブロッキング」が潜在的な原因から除外されます。フリーズの原因は、メインスレッド上の計算作業のみになります。

    今必要とするのは、フリーズ中にメインスレッド上で実行されたメソッドを見つけることだけです。これにはホットスポットと呼び出しツリーフィルターを使用できます。

15. スレッドの状態フィルターで実行を選択します。これにより、結果のフィルターは「UI フリーズが発生したときにメインスレッドが実行されていて、ブロッキング GC が実行されなかったすべての時間間隔を選択する」になります。フィルターのリストは次のようになります。

    

    フィルターホットスポットと呼び出しツリーには、これらの時間間隔で実行されたメソッドのみが含まれています。

16. パフォーマンスプロファイラウィンドウで、ホットスポットをクリックして対応するフィルターを開きます。実行時間別にソートされたユーザーメソッドの単純なリストを示しています。ユーザーメソッドの実行時間は、メソッド自身の時間と、それが呼び出すすべてのシステムメソッドの自分の時間（スタック内の次のユーザーメソッドまで）の合計として計算されます。

    

    ご覧のとおり、実行時間の意味は 2 つしかありません: App.Main と MainWindow.ProcessInProgress です。

17. 呼び出しツリーを参照してください。

    

    ご覧のように、App.Main は、Windows メッセージの処理に関連する多くのシステムメソッドでほとんどの時間を費やします。* これは、グラフィカルユーザーインターフェースを提供するアプリケーションの典型的な動作です。これは、アプリケーションがメッセージループでユーザー入力を待つことを示します。スナップショットを分析する際には、これらのメソッドを無視することができます。どのメソッドがフリーズを引き起こしているかを知るには、スタック内の次のユーザーメソッドを調べる必要があります。これは MainWindow.ProcessInProgress になります。この方法で何らかの計算作業のために遅延が発生したと仮定したため、そのソースコードを調べてみましょう。

18. 呼び出しツリーで、ProcessInProgress メソッドを右クリックし、コンテキストメニューでコードに移動するを選択します。

    

19. ソースコードを参照してください。

    private void ProcessInProgress(object sender, ProgressChangedEventArgs e) { var upd = (ProgressUpdater) e.UserState; lblProgress.Content = $"File {upd.CurrentFileNmb} of {upd.TotalFiles}: {e.ProgressPercentage}%"; }

    このメソッドは、メインウィンドウの進捗ラベルのファイル処理操作の進行状況を更新するイベントハンドラーにすぎないようです。これらの計算は複雑に見えないため、なぜフリーズが起こったのですか？ どうやら、このイベントハンドラーは非常に頻繁に呼び出され、メインウィンドウはラベルの更新に対処できません。私たちのコードでこれを調べてみましょう。

20. さらにコードの調査 * は、このイベントハンドラーが背景ワーカーの ProgressChanged イベントに登録されていることを示しています。このイベントは、ワーカーが ReportProgress メソッドを呼び出すときに発生します。これは、背景ワーカーの ProcessFiles メソッドから呼び出されます。

    ... for (int j = 0; j < _lines.Length; j++) { var line = _lines[j]; var stringReverser = new StringReverser(line); _lines[j] = stringReverser.Reverse(); if (j % 5 == 0) { var p = ((float)(j + 1) / _lines.Length) * 100; Worker.ReportProgress((int) p, _updater); } } ...

21. パフォーマンスの問題の原因は次のとおりです。ReportProgress は、テキストファイル内の 5 行が処理されるたびに呼び出されます。ラインが非常に迅速に処理されるため、ReportProgress はシステムにとって非常に頻繁に呼び出されます。たとえば、この回線を 1000 回線あたり 1 つのコールに減らしましょう。コード内の if 条件を改善します。

    ... if (j % 1000 == 0) { float _p = ((float)(j + 1) / _lines.Length) * 100; Worker.ReportProgress((int) _p, _updater); } ...

22. プロファイラの実行とスナップショットの取得に従って、ソリューションを再構築し、もう一度プロファイリングを実行します。

    

    いいえ、それ以上の遅れはありません ! タイムラインは、ファイル処理中に UI がフリーズすることも検出しません。

結論

ここでは主なチュートリアルを紹介します:

• 「古典的」パフォーマンスプロファイリングとは異なり、タイムラインプロファイリング中に、dotTrace は一時コールスタックとスレッド状態データを収集します。

• タイムラインプロファイリングの結果を分析するには、Visual Studio のパフォーマンスプロファイラツールウィンドウまたはスタンドアロンの dotTrace Viewer アプリケーションを使用できます。

• パフォーマンスプロファイラおよび dotTrace Viewer は、アプリケーションのイベントタイムラインを視覚化し、収集された一時的なデータを細分化できるフィルターとダイアグラムのセットです。

• 各フィルターはデュアル目的です: データを表示し、特定の条件を設定することができます。

• フィルターは一緒に連鎖することができます。