dotTrace 2020.2ヘルプ

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

警告!このチュートリアルはdotTrace 2016.2のために書かれました。一部のUIコントロール(フィルタなど)は、dotTrace 2016.3で大幅に再設計されています。例:分析サブジェクトフィルターのすべてのコントロールをイベントフィルターに移動しました。

このチュートリアルでは、重要なプロファイリングの手順を詳しく見て、タイムラインビューアーのユーザーインターフェースを紹介します。また、サンプルアプリケーションをプロファイルし、UIがフリーズする理由を判断しようとします。これは非常に一般的なプロファイリングタスクです。

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

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

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

t1 app png

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

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

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

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

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

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

    t1 profiling options png

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

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

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

    t1 app png

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

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

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

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

  1. スレッドをクリックしてスレッドツールウィンドウを開きます。既定では、アンマネージスレッドを除くすべてのアプリケーションスレッドが表示されます。*表示されるすべてのフィルタ値は、現在表示されているすべてのスレッドについて計算されます。さらに分析するために、作業をしないスレッドには興味がありません。まず取り除きましょう。
    t1 threads png
  2. ツールウィンドウのスレッドのリストを参照してください。メインアプリケーションスレッド、実行時にオブジェクトをファイナライズするために使用するファイナライザスレッド(アプリケーションでは機能しません)、およびガーベッジ・コレクションスレッド(バックグラウンドGCの実行に使用)が含まれています。バックグラウンドスレッドはCLRスレッドプールによって作成されるため、アプリケーションのファイルを処理する BackgroundWorker スレッドはスレッドプール(ID 13456)と識別されます。もう1つのスレッドプール(ID 7416)も動作しません。これは、おそらく補助CLRスレッドプールです。私たちの分析と無関係なファイナライザスレッドプール(ID 7416)スレッドを隠してみましょう。

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

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

    t1 hide threads png

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

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

  6. スレッドダイアグラムの現在のスケールは、13456スレッドプール(私たちの BackgroundWorker スレッド)を詳細に見ることができません。全体の図に収まるように拡大しましょう。これを行うには、スレッド図*で Mouse Wheel を使用します。これにより、可視時間範囲(1489 ミリ秒)でフィルタが自動的に追加されます。このフィルタが他のフィルタに与える影響に注意してください。すべての値は、可視の時間範囲で再計算されます。次のフィルタがスナップショットデータmsgstr "非表示のスレッドを除くすべてのスレッドに対して、表示可能な時間範囲内のすべての時間間隔を選択する"に適用されます。
    t1 visible interval filter png
  7. スレッドダイアグラムを参照してください。見ているのは、スレッド状態がどのように変化したかです。例:私たちの BackgroundWorker スレッド13456スレッドプールは、(プロセスファイルボタンをクリックして)約16秒で開始しました。ほとんどの時間はスレッドが実行(濃い青色の間隔)でした。また、スレッドが待機状態(薄い青色の間隔)にあった間隔があります。

    t1 zoomed thread png

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

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

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

    t1 process overview png
  9. まず、可視の時間範囲フィルタを不要にして、それを削除しましょう。これを行うには、スレッドツールウィンドウ*の上にあるフィルタをクリックします。ダイアグラムがズームアウトします。
    t1 remove filter png
  10. 次に、UIのフリーズイベントをより詳細に調べてみましょう。このようなフリーズの主な原因は何ですか?これらは:
    • 長いまたは頻繁なブロッキングGC;

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

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

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

    t1 ui freeze filter png

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

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

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

    t1 blocking gc filter png

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

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

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

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

    t1 thread state filter png

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

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

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

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

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

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

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

    t1 navigate to code png

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

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

結論

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

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

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

  • パフォーマンスプロファイラタイムラインビューアーは、アプリケーションのイベントタイムラインを視覚化し、収集された時間的データをスライスしてサイジングすることを可能にする一連のフィルタとダイアグラムです。

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

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

最終更新日: 2020年5月08日