SteamVR/Frame Timing

From Valve Developer Community
Jump to: navigation, search

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.

FrameTiming Button.png


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

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 (https://github.com/ValveSoftware/openvr/wiki/IVRCompositor_Overview), 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 requires 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.

FrameTiming InHeadset.png


Clicking 'Details' shows a breakdown of all the individual timing being tracked. Use the checkbox next to each label to filter the data.

FrameTiming Details.PNG


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


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.

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


'Late Start' is a special case where the application has exceeded its cpu budget for the frame, but has not yet dropped a frame due to this. This extra wiggle room comes from what we call 'running start'; it provides a 3ms buffer before the frame starts (i.e. vsync), for the application to begin feeding the gpu render commands for that frame.

More on this here: http://www.gdcvault.com/play/1021771/Advanced-VR.

In this example, you can see at frame 7964 the application did not hand off to the compositor until very near the end of the frame. This ate into its 'running start' time for the next frame, indicated by the red 'Late Start'. You can also see how this affects the gpu by introducing a bubble (idle time) indicated by the brownish 'Other' growing correspondingly. Here also, we see that because we've gotten so close to dropping frames by frame 7966, interleaved reprojection kicks in. The yellow idle time also jumps up (and off the top of the scale) indicating the application now has twice the budget to work with, and after three additional frames under budget, drops back to normal. This whole process repeats itself again about 60 frames later in this example.

FrameTiming LateStart.PNG


Switching over to details view, we can see that something happened in the application to cause it to call WaitGetPoses much later than normal in these two cases. At this point, you would need to dig into your application's profiler to determine the cause of that.

FrameTiming LateStartDetails.PNG


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