From 5478bad3d0a2dd0ea177b9f1a782c34b7d2fa4f5 Mon Sep 17 00:00:00 2001
From: Christoph Haag <christoph.haag@collabora.com>
Date: Thu, 5 Nov 2020 20:07:53 +0100
Subject: [PATCH] st/oxr: Add OXR_FRAME_TIMING_SPEW var to print basic frame
 timing information

---
 src/xrt/state_trackers/oxr/oxr_objects.h |  5 +++
 src/xrt/state_trackers/oxr/oxr_session.c | 44 ++++++++++++++++++++++++
 2 files changed, 49 insertions(+)

diff --git a/src/xrt/state_trackers/oxr/oxr_objects.h b/src/xrt/state_trackers/oxr/oxr_objects.h
index 40534398f..b5e1b1cbb 100644
--- a/src/xrt/state_trackers/oxr/oxr_objects.h
+++ b/src/xrt/state_trackers/oxr/oxr_objects.h
@@ -1330,6 +1330,11 @@ struct oxr_session
 	 */
 	float ipd_meters;
 
+	/*!
+	 * Frame timing debug output.
+	 */
+	bool frame_timing_spew;
+
 	/*!
 	 * To pipe swapchain creation to right code.
 	 */
diff --git a/src/xrt/state_trackers/oxr/oxr_session.c b/src/xrt/state_trackers/oxr/oxr_session.c
index 69cc27fff..4d085a602 100644
--- a/src/xrt/state_trackers/oxr/oxr_session.c
+++ b/src/xrt/state_trackers/oxr/oxr_session.c
@@ -44,6 +44,7 @@
 
 
 DEBUG_GET_ONCE_NUM_OPTION(ipd, "OXR_DEBUG_IPD_MM", 63)
+DEBUG_GET_ONCE_BOOL_OPTION(frame_timing_spew, "OXR_FRAME_TIMING_SPEW", false)
 
 #define CALL_CHK(call)                                                         \
 	if ((call) == XRT_ERROR_IPC_FAILURE) {                                 \
@@ -499,6 +500,22 @@ oxr_session_views(struct oxr_logger *log,
 	return oxr_session_success_result(sess);
 }
 
+static double
+ns_to_ms(int64_t ns)
+{
+	double ms = ((double)ns) * 1. / 1000. * 1. / 1000.;
+	return ms;
+}
+
+static double
+ts_ms(struct oxr_session *sess)
+{
+	timepoint_ns now = time_state_get_now(sess->sys->inst->timekeeping);
+	int64_t monotonic =
+	    time_state_ts_to_monotonic_ns(sess->sys->inst->timekeeping, now);
+	return ns_to_ms(monotonic);
+}
+
 XrResult
 oxr_session_frame_wait(struct oxr_logger *log,
                        struct oxr_session *sess,
@@ -525,10 +542,20 @@ oxr_session_frame_wait(struct oxr_logger *log,
 	sess->active_wait_frames++;
 	os_mutex_unlock(&sess->active_wait_frames_lock);
 
+	if (sess->frame_timing_spew) {
+		oxr_log(log, "Called at %8.3fms", ts_ms(sess));
+	}
+
 	// A subsequent xrWaitFrame call must: block until the previous frame
 	// has been begun
 	os_semaphore_wait(&sess->sem, 0);
 
+	if (sess->frame_timing_spew) {
+		oxr_log(log,
+		        "Finished waiting for previous frame begin at %8.3fms",
+		        ts_ms(sess));
+	}
+
 	uint64_t predicted_display_time;
 	uint64_t predicted_display_period;
 	CALL_CHK(xrt_comp_wait_frame(xc, &sess->frame_id.waited,
@@ -553,6 +580,15 @@ oxr_session_frame_wait(struct oxr_logger *log,
 		    frameState->predictedDisplayTime);
 	}
 
+	if (sess->frame_timing_spew) {
+		oxr_log(log,
+		        "Waiting finished at %8.3fms. Predicted display time "
+		        "%8.3fms, "
+		        "period %8.3fms",
+		        ts_ms(sess), ns_to_ms(predicted_display_time),
+		        ns_to_ms(predicted_display_period));
+	}
+
 	return oxr_session_success_result(sess);
 }
 
@@ -1867,6 +1903,13 @@ oxr_session_frame_end(struct oxr_logger *log,
 		    frameEndInfo->displayTime);
 	}
 
+	int64_t timestamp = time_state_ts_to_monotonic_ns(
+	    sess->sys->inst->timekeeping, frameEndInfo->displayTime);
+	if (sess->frame_timing_spew) {
+		oxr_log(log, "End frame at %8.3fms with display time %8.3fms",
+		        ts_ms(sess), ns_to_ms(timestamp));
+	}
+
 	struct xrt_compositor *xc = sess->compositor;
 
 	/*
@@ -2250,6 +2293,7 @@ oxr_session_create(struct oxr_logger *log,
 	}
 
 	sess->ipd_meters = debug_get_num_option_ipd() / 1000.0f;
+	sess->frame_timing_spew = debug_get_bool_option_frame_timing_spew();
 
 	oxr_session_change_state(log, sess, XR_SESSION_STATE_IDLE);
 	oxr_session_change_state(log, sess, XR_SESSION_STATE_READY);