Frame diagnostics: thread CPU and waits in [vr-perf], load and exit_seconds keys, perf_run.sh (dev only)

[vr-perf] now has the game thread's own CPU time per frame (CLOCK_THREAD_CPUTIME_ID), the
time in xrWaitFrame and in acquiring the swapchain image (with its wait), and the eye size, so
the split between work and waiting is there (lessons 39, 50, 62). The load key loads a save
instead of starting a map, exit_seconds leaves after that many seconds of rendering.
perf_run.sh does one run and adds the Adreno's time at each frequency over it.

Projects/Android/jni/src/Lambda1VR/TBXR_Common.c

@@ -734,6 +734,9 @@ void ovrFramebuffer_Resolve(ovrFramebuffer* frameBuffer) {
 }
 
 void ovrFramebuffer_Acquire(ovrFramebuffer* frameBuffer) {
+#ifdef L1VR_STEAM_FRAME
+    const double acquireStart = TBXR_GetTimeInMilliSeconds();
+#endif
     // Acquire the swapchain image
     XrSwapchainImageAcquireInfo acquireInfo = {XR_TYPE_SWAPCHAIN_IMAGE_ACQUIRE_INFO, NULL};
     OXR(xrAcquireSwapchainImage(
@@ -753,6 +756,9 @@ void ovrFramebuffer_Acquire(ovrFramebuffer* frameBuffer) {
                 i,
                 waitInfo.timeout * (1E-9));
     }
+#ifdef L1VR_STEAM_FRAME
+    VrDiag_NoteTiming(VRDIAG_TIME_ACQUIRE, TBXR_GetTimeInMilliSeconds() - acquireStart);
+#endif
 }
 
 void ovrFramebuffer_Release(ovrFramebuffer* frameBuffer) {
@@ -2295,7 +2301,13 @@ void TBXR_FrameSetup()
 	gAppState.FrameState.type = XR_TYPE_FRAME_STATE;
 
 	ALOGV("xrWaitFrame");
+#ifdef L1VR_STEAM_FRAME
+	const double waitStart = TBXR_GetTimeInMilliSeconds();
+#endif
 	OXR(xrWaitFrame(gAppState.Session, NULL, &gAppState.FrameState));
+#ifdef L1VR_STEAM_FRAME
+	VrDiag_NoteTiming(VRDIAG_TIME_WAIT_FRAME, TBXR_GetTimeInMilliSeconds() - waitStart);
+#endif
 
 	// Get the HMD pose, predicted for the middle of the time period during which
 	// the new eye images will be displayed. The number of frames predicted ahead

Projects/Android/jni/src/Lambda1VR/VrDiag.c

@@ -3,6 +3,7 @@
 #include <string.h>
 #include <sys/stat.h>
 #include <math.h>
+#include <time.h>
 
 #include <common/common.h>
 #include <client/client.h>
@@ -37,9 +38,26 @@ static bool dumpEyeDone[2];
 static double windowStart = 0.0;
 static double lastBegin = 0.0;
 static double cpuSum = 0.0;
+static double waitSum = 0.0, acquireSum = 0.0;	// ms in xrWaitFrame and xrAcquireSwapchainImage (+ its wait)
+static double threadStart = 0.0, threadCpuNow = 0.0;	// the game thread's CPU time
 static long windowFrames = 0;
 static long windowMissed = 0;
 
+void VrDiag_NoteTiming(int what, double ms)
+{
+	if (what == VRDIAG_TIME_WAIT_FRAME)
+		waitSum += ms;
+	else
+		acquireSum += ms;
+}
+
+static double threadCpuMs(void)
+{
+	struct timespec now;
+	clock_gettime(CLOCK_THREAD_CPUTIME_ID, &now);
+	return now.tv_sec * 1000.0 + now.tv_nsec / 1e6;
+}
+
 void VrDiag_Init(void)
 {
 	VrDiagCore_Defaults(&config);
@@ -465,6 +483,8 @@ void VrDiag_FrameBegin(void)
 	}
 
 	const double now = TBXR_GetTimeInMilliSeconds();
+	if (threadStart == 0.0)
+		threadStart = threadCpuMs();
 	frames++;
 	if (TBXR_ShouldRender())
 	{
@@ -490,9 +510,16 @@ void VrDiag_FrameBegin(void)
 	if (config.perf && (now - windowStart) >= 10000.0)
 	{
 		const double seconds = (now - windowStart) / 1000.0;
-		ALOGI("[vr-perf] fps=%.1f missed=%ld cpu_ms=%.2f period_ms=%.2f frames=%ld rendered=%ld game=%s",
-			  windowFrames / seconds, windowMissed, windowFrames ? cpuSum / windowFrames : 0.0,
-			  gAppState.FrameState.predictedDisplayPeriod / 1e6, frames, renderedFrames, connectionName());
+		// the thread's own CPU time over the window, against the wall time: what's left is waiting
+		const double threadMs = threadCpuMs();
+		const double cpuPerFrame = windowFrames ? (threadMs - threadStart) / windowFrames : 0.0;
+		ALOGI("[vr-perf] fps=%.1f missed=%ld cpu_ms=%.2f thread_cpu_ms=%.2f wait_ms=%.2f acquire_ms=%.2f period_ms=%.2f frames=%ld rendered=%ld size=%d game=%s",
+			  windowFrames / seconds, windowMissed, windowFrames ? cpuSum / windowFrames : 0.0, cpuPerFrame,
+			  windowFrames ? waitSum / windowFrames : 0.0, windowFrames ? acquireSum / windowFrames : 0.0,
+			  gAppState.FrameState.predictedDisplayPeriod / 1e6, frames, renderedFrames,
+			  gAppState.Renderer.FrameBuffer[0].Width, connectionName());
+		threadStart = threadMs;
+		waitSum = acquireSum = 0.0;
 		windowStart = now;
 		windowFrames = 0;
 		windowMissed = 0;
@@ -503,7 +530,10 @@ void VrDiag_FrameBegin(void)
 	if (config.autostart && !mapStarted && renderedFrames >= 150)
 	{
 		char command[96];
-		snprintf(command, sizeof(command), "map %s\n", config.map[0] ? config.map : "c1a0");
+		if (config.load[0])
+			snprintf(command, sizeof(command), "load %s\n", config.load);
+		else
+			snprintf(command, sizeof(command), "map %s\n", config.map[0] ? config.map : "c1a0");
 		Cbuf_AddText(command);
 		mapStarted = true;
 		mapStartFrame = renderedFrames;
@@ -520,6 +550,16 @@ void VrDiag_FrameBegin(void)
 		ALOGI("[vr-diag] cmd: %s", config.cmd);
 	}
 
+	static double firstFrameMs = 0.0;
+	if (firstFrameMs == 0.0)
+		firstFrameMs = now;
+	if (config.exitSeconds > 0 && (now - firstFrameMs) >= config.exitSeconds * 1000.0)
+	{
+		ALOGI("[vr-diag] exit_seconds %d reached, shutting down", config.exitSeconds);
+		config.exitSeconds = 0;
+		TBXR_exit(0);
+	}
+
 	if (config.exitAfter > 0 && frames >= config.exitAfter)
 	{
 		ALOGI("[vr-diag] exit_after %d reached, shutting down", config.exitAfter);

Projects/Android/jni/src/Lambda1VR/VrDiag.h

@@ -24,4 +24,8 @@ bool VrDiag_SyntheticHand(int hand, ovrTrackedController* controller);
 bool VrDiag_InjectInputs(frameRaw_t* raw);
 bool VrDiag_Injecting(void);
 
+// time spent in the blocking XR calls, for the [vr-perf] split between work and waiting
+enum { VRDIAG_TIME_WAIT_FRAME, VRDIAG_TIME_ACQUIRE };
+void VrDiag_NoteTiming(int what, double ms);
+
 #endif

Projects/Android/jni/src/Lambda1VR/VrDiagCore.c

@@ -162,6 +162,15 @@ int VrDiagCore_Parse(const char* text, vrDiagConfig_t* config)
 		{
 			config->autostart = number != 0;
 		}
+		else if (strcasecmp(key, "load") == 0 && *value != '\0')
+		{
+			snprintf(config->load, sizeof(config->load), "%s", value);
+			config->autostart = 1;
+		}
+		else if (strcasecmp(key, "exit_seconds") == 0 && parseInt(value, &number))
+		{
+			config->exitSeconds = number > 0 ? number : 0;
+		}
 		else if (strcasecmp(key, "map") == 0 && *value != '\0')
 		{
 			snprintf(config->map, sizeof(config->map), "%s", value);

Projects/Android/jni/src/Lambda1VR/VrDiagCore.h

@@ -22,6 +22,8 @@ typedef struct {
 	int pressCount;
 	float roll;			// synthetic head roll in degrees (tilting the head to the left is positive)
 	int autostart;		// load a map without touching the menus
+	char load[64];		// a save to load instead of starting a map (a load key implies autostart)
+	int exitSeconds;	// leave after this many seconds of rendering, 0 = off
 	char map[64];		// which one (a map set here starts it as well)
 	char cmd[128];		// console commands (; between them) to run once, about 4 s after the map starts
 	int dumpFrame;		// dump both eyes on this rendered frame, 0 = off

tools/steam_frame/perf_run.sh

@@ -0,0 +1,61 @@
+#!/usr/bin/env bash
+# One unattended performance run: starts the game with force_render for N seconds with the given
+# diag keys, then prints the [vr-perf] lines of the run and the Adreno's time at each frequency over it
+# (devfreq trans_stat, so the share at the top frequency says if the GPU was saturated).
+#
+#   tools/steam_frame/perf_run.sh --lock-holder NAME [--seconds 70] [--load SAVE | --map MAP] [--diag K=V ...]
+#
+# Several runs per setting, and say what the setting was (the first [vr-perf] line has the eye size and the rate):
+# a single run can be a compositor state, not the setting (lesson 67).
+set -euo pipefail
+root="$(cd "$(dirname "$0")/../.." && pwd)"
+frame_host="${FRAME_HOST:-steamos@192.168.1.31}"
+seconds=70
+holder=""
+start=()
+diag=()
+while (($#)); do
+    case "$1" in
+        --lock-holder) holder="$2"; shift 2 ;;
+        --seconds) seconds="$2"; shift 2 ;;
+        --load) start=(--diag "load=$2"); shift 2 ;;
+        --map) start=(--diag "map=$2"); shift 2 ;;
+        --diag) diag+=(--diag "$2"); shift 2 ;;
+        *) echo "unknown option $1" >&2; exit 1 ;;
+    esac
+done
+[[ -n "$holder" ]] || { echo "need --lock-holder" >&2; exit 1; }
+gpu='/sys/class/devfreq/3d00000.gpu/trans_stat'
+snap() { ssh -o BatchMode=yes "$frame_host" "cat $gpu" 2>/dev/null || true; }
+
+"$root/tools/steam_frame/deploy.sh" --lock-holder "$holder" --no-install --diag-reset --clear-dumps \
+    --diag force_render=1 --diag perf=1 "${start[@]}" "${diag[@]}" --diag "exit_seconds=$((seconds))" --no-launch >/dev/null 2>&1
+before="$(snap)"
+"$root/tools/steam_frame/deploy.sh" --lock-holder "$holder" --no-install --logcat $((seconds + 12)) 2>&1 | grep -E "vr-perf|\[openxr\] (refresh|eye image|frame period)|FORTIFY" || true
+after="$(snap)"
+python3 - "$before" "$after" <<'PY'
+import sys
+def rows(t):
+    r = {}
+    for line in t.splitlines():
+        line = line.replace("*", " ")
+        if ":" in line and line.strip()[0].isdigit():
+            head, _, rest = line.partition(":")
+            try:
+                r[int(head.strip())] = int(rest.split()[-1])
+            except (ValueError, IndexError):
+                pass
+    return r
+b, a = rows(sys.argv[1]), rows(sys.argv[2])
+if a and b:
+    d = {k: a[k] - b.get(k, 0) for k in a}
+    total = sum(d.values()) or 1
+    top = max(d)
+    print("gpu devfreq time at each frequency over the run (Hz: ms, share):")
+    for k in sorted(d):
+        if d[k]:
+            print("  %d: %d ms, %.1f%%" % (k, d[k], 100.0 * d[k] / total))
+    print("gpu at the top frequency %d: %.1f%%" % (top, 100.0 * d[top] / total))
+else:
+    print("no devfreq trans_stat")
+PY