NSight SystemsでD3D12のアプリケーションを見る

先日、NVIDIA NSight Systems 2020.2がリリースされました。近年のNSight Systemsは、アップデートを頻繁に行っており、急速にその使いやすさが改善されてきました。特に、D3D12のアプリケーションのCPUとGPUの動きを見るときは非常に有用なツールとなっています。

はじめに

まずは、NSight Systemsの、グラフィックスアプリケーションのデバッグツールのエコシステムでの役割を把握しましょう。NSight Systemsは、NSight Graphicsのようなフレームデバッガとは異なり、個々のドローコールのレンダーステートや、バインドされているシェーダーリソースなどは一切チェックすることができません。また、ドローコールやディスパッチごとのパフォーマンスも知ることができません。これらの情報が知りたいときは、NSight GraphicsやMicrosoft Pixを使うのが適切だと思われます。
一方で、NSight Systemsを使うことで、CPUからGPUへのコマンドリストの送出や、GPUのFenceObjectによる実行同期の状況、CopyQueueやComputeQueuの並列動作のタイミングなどを詳しく知ることができます。また、同じような役割を持つツールとして、Windows Performance Toolkitに含まれるGPUViewというものがあります。しかし、こちらはOSレベルでのトレースログとなるので、使いこなすためには、それなりの前提知識が必要です。対して、NSight Systemsは、基本的にはアプリケーションレベルの解析結果を提供するので、アプリケーションを作った本人ならば、理解は比較的容易と思われます。
トレースログの取り方も両者には大きな違いがあります。NSight GraphicsやMicrosoft Pixはフレームプロファイラなので、基本的には1フレーム分のGPUタスクを詳細にキャプチャします。対して、NSight SystemsやGPUViewは、レンダリングのタイミングと関係なく複数フレームを含む一定時間をキャプチャします。両者の役割を考えれば自然な事なのですが、役割の違いがログの取り方にも表れています。ここでは余談ですが、NSight Systemsは、CUDAアプリケーションの解析することができるので、実はCUDA開発者の間では非常に一般的に用いられているツールです。

プロファイルのためのレポート(トレースログ)を取得してみる

早速ですが、D3D12で動作している、比較的シンプルなグラフィックスサンプルアプリケーションを見てみましょう。File -> NewProjectメニュー選択して新しいプロジェクトを作成します。一つのプロジェクトにつき、一つのターゲットアプリケーションが一般的です。ここでは一つの例としてRTXGI-SDKのサンプルをターゲットアプリケーションに見立てて設定します。
まず初めに、トレースログを取得するマシンとの接続を確立します。今回はローカルマシンをターゲットにしますので、一番上のLocal Host Connectionのドロップダウンリストから自分のマシンを選択します。するとターゲットと自動的に接続が確立します。次に、Target Applicationの欄に、アプリケーションの実行バイナリのパスと、必要な引数を設定します。次に”Sample target process” “Collect thread activity”にチェックを入れます。さらに、自身でビルドできるアプリケーションの場合は、”Collect call stacks executing threads”の欄で、シンボルパスの設定をするのをお勧めします。ここにはPDBファイルが配置されているパスを設定します。最後に”Collect DX12 trace”を有効にし、”Trace GPU Workload”, “Trace debug markers”, “Trace wait calls that block on fences”全てにチェックを入れます。ターゲットアプリケーションがDX11や、OpenGLの場合は、適宜対象にあわせて設定を変更します。最後に、ウインドウ右側の”Start Profiling manually”にチェックを入れます。慣れてきたら、アプリケーション起動後に、自動でトレースログを記録したり、自動で終了するモードを使うのも良いと思いますが、ここでは、トレースログの記録開始と終了は手動操作で行います。

 

“Start”ボタンをクリックして、ターゲットアプリケーションを起動します。無事にアプリケーションが起動すれば、プロファイリングのタブが新しく表示されます。ターゲットアプリケーションを操作して、レンダリングを解析したい状況にします。その後、Startボタンを押してトレースログの取得を開始します。Stopボタンを押すまではログが取得され続けます。あまり長い時間キャプチャすると、大きなレポートになって扱いにくいので、一般的なプロファイルであれば、数秒間待ったあとにStopボタンを押します。これで、トレースログが取得できます。ターゲットアプリケーションは終了してもかまいません。トレースログは、自動的にレポートに変換されます。レポートは、ディスク上に保存されているので、NSight Systemを一旦終了させても、後程ロードすれば開くことができます。ファイルはデフォルトの設定では、以下のフォルダにプロジェクトごとにフォルダが作成され、qdrepの拡張子のファイルが個々のレポートに対応します。
%userprofile%\Documents\NVIDIA Nsight Systems\Projects

さっそくレポートを読んでみる

無事レポートへの変換が完了すると、自動的にレポートが表示されます。デフォルトでは以下のようなTimeline Viewが見えていると思います。

 

まず、レポートを詳しく見る前に、左上のドロップダウンリストからAnalysis Summaryを選択します。すると、キャプチャした時のOSやGPU、ドライバーの構成等を確認することができます。これは、他の人がキャプチャしたレポートを見るときに非常に有用です。チェックしておきましょう。

 

それではTimeline Viewに戻ります。
まずはターゲットアプリケーションのCPUスレッドをチェックします。今回のターゲットアプリケーションは、TestHarness.exeという名前です。合計8つのスレッドが確認できます。このアプリケーションのレンダリングは、一つのスレッドで全て処理されているので、一番上のスレッド以外はあまりレンダリングに関係ありません。残りのスレッドは全て非表示にします。スレッドの表示、非表示の切り替えは、スレッドの欄の一番下のプラス、マイナスのボタンをクリックするか、Tree ViewのThreadsの位置で、右クリックをして、Show more, Show lessを選択することで行います。アプリケーションによっては複数のスレッドがD3D12のCommand Listの生成やQueueへのSubmitを行う場合もあるので、その場合は複数のスレッドを同時にチェックする必要があるでしょう。また、今回は、他のプロセス([4]System, [3476] MemCompression)等の表示は畳んでおきます。すると以下のようになります。

 

次に、Timeline Viewで非常によく使うキーボードショートカットを以下に示します。基本的に修飾キー+マウスWheelなので、簡単です。

  • Shift + Mouse Wheel
    Timeline Viewの縦スクロール
  • Alt + Mouse Wheel
    Timeline Viewの横スクロール
  • Ctrl + Mouse Wheel
    Timeline Viewのズームイン、ズームアウト

まずは、これらのショートカットを使って、自由にTimeline View操作しましょう。

フレーム処理時間をチェックする

まず、プロファイルを始めるにあたり、一番簡単に検証できることから始めます。それは、1フレームあたりのCPU処理時間を調べることです。CPU Frame Durationの段に注目します。これはCPU側の1フレームの処理の長さを表しています。1フレームあたりのの処理時間が十分に見やすくなるまでズームインし、どれが一つを選択して、ハイライトします。ここではフレーム番号17のフレームを選択しています。31.55msの長さがあります。

 

次に、同じフレームがGPU側で処理されている個所を確認します。CPU Frame Durationの少し下の段に、使用しているGPUの名前の段があります。そこで、同様に17番のFrameを選択します。こちらは16.23msでした。

上記二つのスクリーンショットは、同じタイムフレームを示しています。これらを見ると分かる通り、CPUはGPUに対して2フレーム先行しているのが分かります。そして、CPUの方がGPUよりもフレーム処理時間が長いです。一方で、GPUのタイムラインでは、何も処理をしていない区間があるのが分かります。ここで、一番下のVSYNCの段に注目すると、GPUの処理が、このタイミングと同期しているのが分かります。つまり、GPU処理の一番最後にあると考えられる、Present処理がVsyncと同期していることが予想できます。実際に、1VSyncインターバルの16.6ms以下でGPU処理が完了した#17のGPUフレームに続く、#18のGPUフレームは、連続するVSyncインターバルで処理されています。一方で、16.6msを超えたフレームでは次のVSyncが来るまでPresentの実行がブロックされている様子が見て取れます。

次に、もう一度CPU処理側に目を移すと、処理時間に大きなばらつきがあります。以下にTimelineを少しズームアウトしたスクリーンショットを示します。CPU Frame Durationの色が、処理時間の長さに応じて変化しているのがわかると思います。GPUのFrame Durationも同様です。これら色の変化に気を配ると、ズームアウトした長い区間から、稀に発生するような処理落ち等を簡単に見つけ出すことができます。今回も、CPUのフレーム処理時間が大きく変化する状況を簡単に見つけ出す事ができましたが、もっと実践的なケースでは、シェーダーのコンパイルや、リソースのロードに起因する稀なフレームレートの低下を素早く検証するのに有用です。

 

GPU処理を詳しく見てみる

では、先ほどハイライトした、#17のGPUフレームを拡大してみます。右側のTree Viewには、GPUの名前とCommand Queueの種類が記載されています。Directと書いてあるので、COMMAND_LIST_TYPE_DIRECTのキューであることが分かります。そして、そのQueueのタスクが処理されるときは、Graphics Workloadと書かれたグラフが表示されます。該当するGraphics WorkloadのCommand Listに、Event Markerが付与されている場合は、その下段にある、GPU Command List Markersに、そのとき処理しているGPUタスクに付与されたEvent Markerの名前が表示されます。Event Markerがネストしている場合は、上から下に向かってスタックされます。今回はこれらの個々のタスクの内容に細かく触れませんが、RTXGIの設定したEvent Markerが見て取れます。

 

次に、Command Queueの段にある、Graphics Wrokloadをクリックしてハイライトします。すると、一段下のAPIと書かれた段と、いくらか上の方段にある、CPU側のタスクのDX12 APIと書かれた段に水色のマーカーが付いたの見て取れます。また、一番上のタイムラインの左側には、左向きの矢印が表示されています。これらは、今選択してハイライトしているタイムライン上のオブジェクトと関連のあるものが、ハイライトされた他の段にあることを示し、左向きの矢印は、その関連のあるイベントが、タイムラインの左側にあることを示しています。

 

ここで少しズームアウトして、それら関連のあるイベントを見てみます。関連のあるイベントが、現在表示されているタイムフレームに入ると、左上の矢印は消え、代わりにタイムライン上に、水色のハイライトが付きます。これを目印に探すことで、タイムライン上で非常に小さく短期間の範囲のオブジェクトでも簡単に見つける事ができます。

 

見つけたオブジェクトにマウスカーソルを合わせると、情報が表示されます。CPU側もGPU側も、ExecuteCommandListsの呼び出しと、その処理時間を表しています。これは、先ほどハイライトしたGPU Workloadが、このExecuteCommandListsを通じて生成されたGPUタスクであることを示しています。この時のCPU Frame Durationを見ると、17フレームの終わりごろに呼び出されたExecuteCommandListsであることが分かります。

CPU処理を詳しく見てみる

それでは、あらためて#17のCPU処理を見てみます。Blocked StateとOS rumtime libraryの段を確認すると、31msの処理時間の殆どにあたる29msは、スレッドがブロックされているのが分かります。

 

このアプリケーションは計8本のスレッドが動作しています。念のため全てのスレッドの動作を確認します。左側Tree ViewのThreadsの段で右クリックをして、Show allを選択すると、全てのスレッドが展開されてCPUのアクティビティが確認できます。やはり、ブロックされている区間では、いずれのスレッドも動作していません。つまりCPU側のスレッドは、他の外的要因でブロックされているのが分かります。左側TreeViewのThreadsの段で右クリックをして、Show lessを選択することで、展開したスレッドを再び非表示にすることができます。

 

次にOS runtime librariesの段にある、Win32 Wait APIと書かれたオブジェクトをクリックすると、Windowsのイベント待機APIの呼び出しによって待機した時間と、その呼び出しがあった個所のコールスタックが表示されます。キャプチャの際にシンボルパスを指定してあれば、このコールスタックは名前解決されて関数名が見ることができます。この例では、TestHarness.exe!D3D12::MoveToNextFrameという個所で待機しているのが分かります。

 

一つ上の段にある、Blocked Stateでは、同様の情報を見ることができます。このオブジェクトには、先ほどのコールスタックの呼び出し元になっていた関数名が表示されるので非常に見やすいです。自分でコンパイルできるアプリケーションを解析するときはシンボルパスを設定することを強くお勧めします。

 

せっかくコールスタックが確認できたので、該当箇所のソースコードを見てみます。そこでは、以下のようにWaitForSingleObjectExを呼び出している部分がありました。つまり、ここで、29msの待機が行われていたことが分かります。待機の対象となっているのは、D3DのFenceに関連付けされたEventObjectである事が分かります。つまりこれは、GPUのFneceが指定の値になり、Signalされるまで待機している個所です。

hr = d3d.fence->SetEventOnCompletion(d3d.fenceValues[d3d.frameIndex], d3d.fenceEvent);
if (FAILED(hr)) return false;
WaitForSingleObjectEx(d3d.fenceEvent, INFINITE, FALSE);

 

話をNSight Systemsに戻します。Win32 Wait APIを選択すると、DX12 APIのSynchronizationの段にハイライトが出て、タイムラインに左側の矢印がでます。もう何を意味するかはお分かりだと思います。

 

ズームアウトして関連のあるオブジェクトを見てみましょう。すると1フレーム前の冒頭にFence Signalが設置されているのが分かります。これは、処理的な意味合いでは、2フレーム前の処理がが全て終了した後に設置されたSignalになります。CPUはこれを29msの間待っていたということが分かります。このSignalは、2フレーム前、つまり#15のGPU処理が完了すれば、Signalされるはずです。

 

GPUのタイムラインを確認してみます。確かにGPUタイムラインの#15の処理が終わった直後にこのWin32 Wait APIはブロックが解消されています。

このように、NSight Systemsでは、CPUとGPUに同期処理がある場合、これをタイムライン上で確認できます。さらに、キャプチャ時にシンボルパスを設定していれば、CPU側のコールスタックが確認できるので、CPU側のどの関数でWin32のWait APIを呼び出しているかが、簡単に確認できます。

次に、CPU側の処理で、Win32 Wait APIが解決した後の処理に注目します。処理時間が短いのでズームインします。ここでは、CPUが各種D3D12のAPIを呼び出して、実際のレンダリング処理を行っています。まず、DX12 Command Lists CreationのGraphics Command Listオブジェクトをハイライトします。このオブジェクトは、一つのCommandListがReset(つまり使用開始)されて、Closeするまでの期間を表します。同時に多数のCommandListが使用されるアプリケーションの場合はここにGraphics Command Listのオブジェクトがスタックされます。今回のアプリケーションは、同時に一つのCommandListしか使用していないので一つしかありませんが、ここを確認することでCPU処理全体の、どの箇所でD3D12のコマンドを作っているかが分かります。

 

スレッド[20272]のDX12APIの段を確認するといくつかのD3D12API呼び出しが記録されています。ここに記録されるのは、CommandListのReset, Closeや、Dispatch, Draw、そして、Resourceに対するMap, UnmapやCopy等が記録されます。加えて、CommandQueueのSignalやWaitも記録され、ExecuteCommandListsは、緑色で表示されます。

 

次にCommand Lists Markersの段に注目してみます。少しタイムラインをズームして見ます。ここには、コマンドリストに設定されたEvent Markerが表示されます。これを確認することで、該当スレッドが何のレンダリングを行っているかが確認できるとともに、そのレンダリングのコマンド生成にどのくらいの時間が掛かっているかが分かります。シングルスレッドのレンダリングではあまり意味はありませんが、マルチスレッドのレンダリングでは、しばしば、どのスレッドが、どのレンダリングを担当しているのかわかりにくいことがありますが、Event Markerを見ることができるので、すぐに判別することができます。

 

次にDX12 APIのID3D12CommandQueue::ExecuteCommandListsのオブジェクトを選択します。このAPIは実際にGPUにコマンドリストを送出する命令です。したがって、GPU側のタイムラインにもこの処理のオブジェクトが現れます。さらに、GPU側のAPIと、デバイスのタイムラインにもハイライトが出ています。加えて、タイムラインの右側に矢印が表示されてます。

 

タイムラインをズームアウトして確認してみます。すると、GPUのGraphics Workloadがハイライトされているのが分かります。これで、CPU側からExecuteCommandListsで送出されたコマンドリストが、いつGPUで処理されて、何ms掛かっているのかが分かります。また、逆に、GPUで実行されたWorkloadが、いつ、CPUどのスレッドからから送出されたものかが分かります。

まとめ

今回はターゲットアプリケーションに簡単なものを選びましたので、レンダリング的には見どころもなく面白くなかったですね。