diff --git a/Projects/Android/jni/src/Lambda1VR/TBXR_Common.c b/Projects/Android/jni/src/Lambda1VR/TBXR_Common.c index 7ca0250..e4a97b6 100644 --- a/Projects/Android/jni/src/Lambda1VR/TBXR_Common.c +++ b/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 diff --git a/Projects/Android/jni/src/Lambda1VR/VrDiag.c b/Projects/Android/jni/src/Lambda1VR/VrDiag.c index 181235d..3e93e86 100644 --- a/Projects/Android/jni/src/Lambda1VR/VrDiag.c +++ b/Projects/Android/jni/src/Lambda1VR/VrDiag.c @@ -3,6 +3,7 @@ #include #include #include +#include #include #include @@ -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); diff --git a/Projects/Android/jni/src/Lambda1VR/VrDiag.h b/Projects/Android/jni/src/Lambda1VR/VrDiag.h index 2367b92..ef29c86 100644 --- a/Projects/Android/jni/src/Lambda1VR/VrDiag.h +++ b/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 diff --git a/Projects/Android/jni/src/Lambda1VR/VrDiagCore.c b/Projects/Android/jni/src/Lambda1VR/VrDiagCore.c index a632582..6cf9c8d 100644 --- a/Projects/Android/jni/src/Lambda1VR/VrDiagCore.c +++ b/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); diff --git a/Projects/Android/jni/src/Lambda1VR/VrDiagCore.h b/Projects/Android/jni/src/Lambda1VR/VrDiagCore.h index e758ff6..a893d99 100644 --- a/Projects/Android/jni/src/Lambda1VR/VrDiagCore.h +++ b/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 diff --git a/tools/steam_frame/perf_run.sh b/tools/steam_frame/perf_run.sh new file mode 100755 index 0000000..666bfea --- /dev/null +++ b/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