Difference between revisions of "SteamVR/Frame Timing"

From Valve Developer Community
Jump to: navigation, search
(Created page with "To display frame timing, right click on vrmonitor, and select Display Frame Timing under Diagnostics. 600px Click 'show in headset' to...")
 
Line 1: Line 1:
To display frame timing, right click on vrmonitor, and select Display Frame Timing under Diagnostics.
+
To display the frame timing graph, right-click on the SteamVR status window and select Settings.
  
[[Image:Steamvr frametiming menu.png|600px]]
+
[[Image:SteamVR_Status.PNG]]
  
Click 'show in headset' to bring up the display in VR as well.  This will show up on the back side of your right most controller (or at the origin if no controllers are attached).
 
  
Here's some example output:
+
Then click on Performance, find the Display Frame Timing button and click it.
  
[[Image:Steamvr frametiming example.png|600px]]
+
[[Image:FrameTiming_Button.png]]
  
This view attempts to show you how your frame time is spent.  The reported times are stacked: solid yellow (e.g. under the blue spike near the left) represents the cpu delay before rendering started for that frame.  Blue is the amount of time spent rendering that frame on the gpu while green is the amount of time spent rendering in the compositor.
 
  
This example was captured while the expensive high quality overlay was in use, so the compositor is taking up way more time than it would otherwise.
+
The default view splits out cpu and gpu performance in a pair of stacked graphs:
  
Switching to raw mode shows a bit more info.  This mode is not stacked - all values represent isolated timings.  The labels along the right indicate which color matches which line and can be toggled on and off to make it easier to read (or help determine which line is which).
+
[[Image:FrameTiming_Stacked.PNG]]
  
* '''frame''' - this value should remain at a stead 11.1ms for headsets running at 90hz, and will spike up to higher intervals when dropping frames
 
* '''prediction''' - this shows the number of ms we are predicting ahead each frame
 
* '''scene gpu''' - the time spent rendering the scene
 
* '''distort gpu''' - the time spent rendering in the compositor (distortion pass plus any overlays, hardbounds, etc.)
 
* '''distort cpu''' - cpu time spent between getting a new frame and calling present
 
* '''scene cpu''' - cpu time between calling WaitGetPoses and Submitting scene textures for both eyes (includes any IPC overhead)
 
* '''running start''' - amount of running start time used (should hover around 3ms)
 
* '''present''' - cpu time taken by the call to D3D Present (this can stall in certain situations - e.g. when the compositor loses fullscreen)
 
  
[[Image:Steamvr frametiming example raw.png|600px]]
+
The blue sections are time spent by the application; these are further split between 'scene' and 'other'.  The 'scene' portion is the amount of work performed between when WaitGetPoses returns, and the second eye texture is Submitted, while 'other' is any time spent after this for rendering the application's companion window, etc.  The cpu timing here does not capture any parallel work being performed (e.g. on your application's main thread).  The brown 'Other' section in the gpu timing reflects any gpu bubbles, context switching overhead, or gpu work from other application getting scheduled in between other segments of work for that frame.  To examine this in more detail require use of gpuview.
  
The slider will allow you to zoom in and out. When you zoom in far enough, the stacked view will change to a bar graph.
+
https://developer.valvesoftware.com/wiki/SteamVR/Installing_GPUView
  
In this capture, we dropped a frame, then had some delayed rendering (before the scene itself started rendering), then dropped a second frame before things get going for real.  That tall cyan bar on the second spike represents the delay before [https://github.com/ValveSoftware/openvr/wiki/IVRCompositor::WaitGetPoses WaitGetPoses] was called for that frame.  It's the inverse of the running start time; normally WaitGetPoses should be getting called 3ms before the frame starts (-3ms on the graph, which we don't display).
 
  
[[Image:Steamvr frametiming example bars.png|600px]]
+
Clicking 'Show in Headset' will display this graph in VR as well.  This will show up on the back side of your right controller (or at the origin if no controllers are attached).  You'll notice the green gpu band take a bit more time when this graph is visible in VR, as rendering Overlays incurs additional work by the compositor.
  
Switching to raw mode, we can see that initial spike was due to '''scene cpu''' time (maybe we're calling WaitGetPoses before we're ready to start rendering for real).  You can also see the '''running start''' time coming from below zero on that first frame.  This is perhaps to be expected since it's the first frame, though we might be able to do better here.
 
  
[[Image:Steamvr frametiming example bars raw.png|600px]]
+
Clicking 'Details' shows a breakdown of all the individual timing being tracked.  This is the same data returned by IVRCompositor.GetFrameTiming.
  
Here's another example from when the compositor has lost fullscreen.  The '''present''' time is blocking until the end of the frame.  This in turn eats into our '''running start''' time (the cyan bits poking up at the bottom), causing a bubble before we start rendering (the solid yellow).  We still make framerate just fine, but this is not ideal.  This example is using the fast compositor shader path, and is more inline with what you should expect for gpu perf there (the little green bits on the tips).
+
<syntaxhighlight lang="cpp">
 +
/** Provides a single frame's timing information to the app */
 +
struct Compositor_FrameTiming
 +
{
 +
uint32_t m_nSize; // Set to sizeof( Compositor_FrameTiming )
 +
uint32_t m_nFrameIndex;
 +
uint32_t m_nNumFramePresents; // number of times this frame was presented
 +
uint32_t m_nNumDroppedFrames; // number of additional times previous frame was scanned out
 +
uint32_t m_nReprojectionFlags;
  
[[Image:Steamvr frametiming present bars.png|600px]]
+
/** Absolute time reference for comparing frames. This aligns with the vsync that running start is relative to. */
 +
double m_flSystemTimeInSeconds;
  
The same view in raw mode:
+
/** These times may include work from other processes due to OS scheduling.
 +
* The fewer packets of work these are broken up into, the less likely this will happen.
 +
* GPU work can be broken up by calling Flush.  This can sometimes be useful to get the GPU started
 +
* processing that work earlier in the frame. */
 +
float m_flPreSubmitGpuMs; // time spent rendering the scene (gpu work submitted between WaitGetPoses and second Submit)
 +
float m_flPostSubmitGpuMs; // additional time spent rendering by application (e.g. companion window)
 +
float m_flTotalRenderGpuMs; // time between work submitted immediately after present (ideally vsync) until the end of compositor submitted work
 +
float m_flCompositorRenderGpuMs; // time spend performing distortion correction, rendering chaperone, overlays, etc.
 +
float m_flCompositorRenderCpuMs; // time spent on cpu submitting the above work for this frame
 +
float m_flCompositorIdleCpuMs; // time spent waiting for running start (application could have used this much more time)
 +
 
 +
/** Miscellaneous measured intervals. */
 +
float m_flClientFrameIntervalMs; // time between calls to WaitGetPoses
 +
float m_flPresentCallCpuMs; // time blocked on call to present (usually 0.0, but can go long)
 +
float m_flWaitForPresentCpuMs; // time spent spin-waiting for frame index to change (not near-zero indicates wait object failure)
 +
float m_flSubmitFrameMs; // time spent in IVRCompositor::Submit (not near-zero indicates driver issue)
 +
 
 +
/** The following are all relative to this frame's SystemTimeInSeconds */
 +
float m_flWaitGetPosesCalledMs;
 +
float m_flNewPosesReadyMs;
 +
float m_flNewFrameReadyMs; // second call to IVRCompositor::Submit
 +
float m_flCompositorUpdateStartMs;
 +
float m_flCompositorUpdateEndMs;
 +
float m_flCompositorRenderStartMs;
 +
 
 +
vr::TrackedDevicePose_t m_HmdPose; // pose used by app to render this frame
 +
};
 +
</syntaxhighlight>
 +
 
 +
[[Image:FrameTiming_Details.PNG]]
 +
 
 +
 
 +
Use the checkbox next to each label to filter the data.  The slider allows you to zoom in and out.  When zoomed in far enough, the stacked view will change to a bar graph, which is useful for seeing individual frame timings.
 +
 
 +
[[Image:FrameTiming_Bars.PNG]]
 +
 
 +
 
 +
A red line is drawn when interleaved reprojection kicks in.  This line represents the threshold required to be below for three consecutive frames before deactivating.
 +
 
 +
[[Image:FrameTiming_Reprojection.PNG]]
 +
 
 +
 
 +
In the details view, you can see the 'running start' interval (indicate here by the black 'New Poses Ready' line) has jumped from the standard 3ms, to almost a full frame to give the application more time to render.
 +
 
 +
[[Image:FrameTiming_ReprojectionDetails.PNG]]
  
[[Image:Steamvr frametiming present raw.png|600px]]
 
  
 
If you see something that doesn't make sense, post about it on the [http://steamcommunity.com/app/358720/discussions/0/ forums].
 
If you see something that doesn't make sense, post about it on the [http://steamcommunity.com/app/358720/discussions/0/ forums].
  
 
[[Category:SteamVR]]
 
[[Category:SteamVR]]

Revision as of 21:06, 1 July 2016

To display the frame timing graph, right-click on the SteamVR status window and select Settings.

SteamVR Status.PNG


Then click on Performance, find the Display Frame Timing button and click it.

File:FrameTiming Button.png


The default view splits out cpu and gpu performance in a pair of stacked graphs:

File:FrameTiming Stacked.PNG


The blue sections are time spent by the application; these are further split between 'scene' and 'other'. The 'scene' portion is the amount of work performed between when WaitGetPoses returns, and the second eye texture is Submitted, while 'other' is any time spent after this for rendering the application's companion window, etc. The cpu timing here does not capture any parallel work being performed (e.g. on your application's main thread). The brown 'Other' section in the gpu timing reflects any gpu bubbles, context switching overhead, or gpu work from other application getting scheduled in between other segments of work for that frame. To examine this in more detail require use of gpuview.

https://developer.valvesoftware.com/wiki/SteamVR/Installing_GPUView


Clicking 'Show in Headset' will display this graph in VR as well. This will show up on the back side of your right controller (or at the origin if no controllers are attached). You'll notice the green gpu band take a bit more time when this graph is visible in VR, as rendering Overlays incurs additional work by the compositor.


Clicking 'Details' shows a breakdown of all the individual timing being tracked. This is the same data returned by IVRCompositor.GetFrameTiming.

/** Provides a single frame's timing information to the app */
struct Compositor_FrameTiming
{
	uint32_t m_nSize; // Set to sizeof( Compositor_FrameTiming )
	uint32_t m_nFrameIndex;
	uint32_t m_nNumFramePresents; // number of times this frame was presented
	uint32_t m_nNumDroppedFrames; // number of additional times previous frame was scanned out
	uint32_t m_nReprojectionFlags;

	/** Absolute time reference for comparing frames.  This aligns with the vsync that running start is relative to. */
	double m_flSystemTimeInSeconds;

	/** These times may include work from other processes due to OS scheduling.
	* The fewer packets of work these are broken up into, the less likely this will happen.
	* GPU work can be broken up by calling Flush.  This can sometimes be useful to get the GPU started
	* processing that work earlier in the frame. */
	float m_flPreSubmitGpuMs; // time spent rendering the scene (gpu work submitted between WaitGetPoses and second Submit)
	float m_flPostSubmitGpuMs; // additional time spent rendering by application (e.g. companion window)
	float m_flTotalRenderGpuMs; // time between work submitted immediately after present (ideally vsync) until the end of compositor submitted work
	float m_flCompositorRenderGpuMs; // time spend performing distortion correction, rendering chaperone, overlays, etc.
	float m_flCompositorRenderCpuMs; // time spent on cpu submitting the above work for this frame
	float m_flCompositorIdleCpuMs; // time spent waiting for running start (application could have used this much more time)

	/** Miscellaneous measured intervals. */
	float m_flClientFrameIntervalMs; // time between calls to WaitGetPoses
	float m_flPresentCallCpuMs; // time blocked on call to present (usually 0.0, but can go long)
	float m_flWaitForPresentCpuMs; // time spent spin-waiting for frame index to change (not near-zero indicates wait object failure)
	float m_flSubmitFrameMs; // time spent in IVRCompositor::Submit (not near-zero indicates driver issue)

	/** The following are all relative to this frame's SystemTimeInSeconds */
	float m_flWaitGetPosesCalledMs;
	float m_flNewPosesReadyMs;
	float m_flNewFrameReadyMs; // second call to IVRCompositor::Submit
	float m_flCompositorUpdateStartMs;
	float m_flCompositorUpdateEndMs;
	float m_flCompositorRenderStartMs;

	vr::TrackedDevicePose_t m_HmdPose; // pose used by app to render this frame
};

File:FrameTiming Details.PNG


Use the checkbox next to each label to filter the data. The slider allows you to zoom in and out. When zoomed in far enough, the stacked view will change to a bar graph, which is useful for seeing individual frame timings.

File:FrameTiming Bars.PNG


A red line is drawn when interleaved reprojection kicks in. This line represents the threshold required to be below for three consecutive frames before deactivating.

FrameTiming Reprojection.PNG


In the details view, you can see the 'running start' interval (indicate here by the black 'New Poses Ready' line) has jumped from the standard 3ms, to almost a full frame to give the application more time to render.

FrameTiming ReprojectionDetails.PNG


If you see something that doesn't make sense, post about it on the forums.