Phase 7.5 timing logs

apps/LoopThroughWithOpenGLCompositing/runtime/presentation/RuntimeStatePresenter.cpp

@@ -83,11 +83,19 @@ JsonValue RuntimeStatePresenter::BuildRuntimeStateValue(const RuntimeStore& runt
 	JsonValue readyQueue = JsonValue::MakeObject();
 	readyQueue.set("depth", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.readyQueueDepth)));
 	readyQueue.set("capacity", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.readyQueueCapacity)));
+	readyQueue.set("minDepth", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.minReadyQueueDepth)));
+	readyQueue.set("maxDepth", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.maxReadyQueueDepth)));
+	readyQueue.set("zeroDepthCount", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.readyQueueZeroDepthCount)));
 	readyQueue.set("pushedCount", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.readyQueuePushedCount)));
 	readyQueue.set("poppedCount", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.readyQueuePoppedCount)));
 	readyQueue.set("droppedCount", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.readyQueueDroppedCount)));
 	readyQueue.set("underrunCount", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.readyQueueUnderrunCount)));
 
+	JsonValue outputRender = JsonValue::MakeObject();
+	outputRender.set("renderMs", JsonValue(telemetrySnapshot.backendPlayout.outputRenderMilliseconds));
+	outputRender.set("smoothedRenderMs", JsonValue(telemetrySnapshot.backendPlayout.smoothedOutputRenderMilliseconds));
+	outputRender.set("maxRenderMs", JsonValue(telemetrySnapshot.backendPlayout.maxOutputRenderMilliseconds));
+
 	JsonValue recovery = JsonValue::MakeObject();
 	recovery.set("completionResult", JsonValue(telemetrySnapshot.backendPlayout.completionResult));
 	recovery.set("completedFrameIndex", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.completedFrameIndex)));
@@ -106,6 +114,7 @@ JsonValue RuntimeStatePresenter::BuildRuntimeStateValue(const RuntimeStore& runt
 	backendPlayout.set("droppedFrameCount", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.droppedFrameCount)));
 	backendPlayout.set("flushedFrameCount", JsonValue(static_cast<double>(telemetrySnapshot.backendPlayout.flushedFrameCount)));
 	backendPlayout.set("readyQueue", readyQueue);
+	backendPlayout.set("outputRender", outputRender);
 	backendPlayout.set("recovery", recovery);
 	root.set("backendPlayout", backendPlayout);
 

apps/LoopThroughWithOpenGLCompositing/runtime/telemetry/HealthTelemetry.cpp

@@ -209,7 +209,9 @@ bool HealthTelemetry::TryRecordPersistenceWriteResult(bool succeeded, const std:
 
 void HealthTelemetry::RecordBackendPlayoutHealth(const std::string& lifecycleState, const std::string& completionResult,
 	std::size_t readyQueueDepth, std::size_t readyQueueCapacity, uint64_t readyQueuePushedCount,
+	std::size_t minReadyQueueDepth, std::size_t maxReadyQueueDepth, uint64_t readyQueueZeroDepthCount,
 	uint64_t readyQueuePoppedCount, uint64_t readyQueueDroppedCount, uint64_t readyQueueUnderrunCount,
+	double outputRenderMilliseconds, double smoothedOutputRenderMilliseconds, double maxOutputRenderMilliseconds,
 	uint64_t completedFrameIndex, uint64_t scheduledFrameIndex, uint64_t scheduledLeadFrames,
 	uint64_t measuredLagFrames, uint64_t catchUpFrames, uint64_t lateStreak, uint64_t dropStreak,
 	uint64_t lateFrameCount, uint64_t droppedFrameCount, uint64_t flushedFrameCount,
@@ -220,10 +222,16 @@ void HealthTelemetry::RecordBackendPlayoutHealth(const std::string& lifecycleSta
 	mBackendPlayout.completionResult = completionResult;
 	mBackendPlayout.readyQueueDepth = readyQueueDepth;
 	mBackendPlayout.readyQueueCapacity = readyQueueCapacity;
+	mBackendPlayout.minReadyQueueDepth = minReadyQueueDepth;
+	mBackendPlayout.maxReadyQueueDepth = maxReadyQueueDepth;
+	mBackendPlayout.readyQueueZeroDepthCount = readyQueueZeroDepthCount;
 	mBackendPlayout.readyQueuePushedCount = readyQueuePushedCount;
 	mBackendPlayout.readyQueuePoppedCount = readyQueuePoppedCount;
 	mBackendPlayout.readyQueueDroppedCount = readyQueueDroppedCount;
 	mBackendPlayout.readyQueueUnderrunCount = readyQueueUnderrunCount;
+	mBackendPlayout.outputRenderMilliseconds = std::max(outputRenderMilliseconds, 0.0);
+	mBackendPlayout.smoothedOutputRenderMilliseconds = std::max(smoothedOutputRenderMilliseconds, 0.0);
+	mBackendPlayout.maxOutputRenderMilliseconds = std::max(maxOutputRenderMilliseconds, 0.0);
 	mBackendPlayout.completedFrameIndex = completedFrameIndex;
 	mBackendPlayout.scheduledFrameIndex = scheduledFrameIndex;
 	mBackendPlayout.scheduledLeadFrames = scheduledLeadFrames;
@@ -240,7 +248,9 @@ void HealthTelemetry::RecordBackendPlayoutHealth(const std::string& lifecycleSta
 
 bool HealthTelemetry::TryRecordBackendPlayoutHealth(const std::string& lifecycleState, const std::string& completionResult,
 	std::size_t readyQueueDepth, std::size_t readyQueueCapacity, uint64_t readyQueuePushedCount,
+	std::size_t minReadyQueueDepth, std::size_t maxReadyQueueDepth, uint64_t readyQueueZeroDepthCount,
 	uint64_t readyQueuePoppedCount, uint64_t readyQueueDroppedCount, uint64_t readyQueueUnderrunCount,
+	double outputRenderMilliseconds, double smoothedOutputRenderMilliseconds, double maxOutputRenderMilliseconds,
 	uint64_t completedFrameIndex, uint64_t scheduledFrameIndex, uint64_t scheduledLeadFrames,
 	uint64_t measuredLagFrames, uint64_t catchUpFrames, uint64_t lateStreak, uint64_t dropStreak,
 	uint64_t lateFrameCount, uint64_t droppedFrameCount, uint64_t flushedFrameCount,
@@ -254,10 +264,16 @@ bool HealthTelemetry::TryRecordBackendPlayoutHealth(const std::string& lifecycle
 	mBackendPlayout.completionResult = completionResult;
 	mBackendPlayout.readyQueueDepth = readyQueueDepth;
 	mBackendPlayout.readyQueueCapacity = readyQueueCapacity;
+	mBackendPlayout.minReadyQueueDepth = minReadyQueueDepth;
+	mBackendPlayout.maxReadyQueueDepth = maxReadyQueueDepth;
+	mBackendPlayout.readyQueueZeroDepthCount = readyQueueZeroDepthCount;
 	mBackendPlayout.readyQueuePushedCount = readyQueuePushedCount;
 	mBackendPlayout.readyQueuePoppedCount = readyQueuePoppedCount;
 	mBackendPlayout.readyQueueDroppedCount = readyQueueDroppedCount;
 	mBackendPlayout.readyQueueUnderrunCount = readyQueueUnderrunCount;
+	mBackendPlayout.outputRenderMilliseconds = std::max(outputRenderMilliseconds, 0.0);
+	mBackendPlayout.smoothedOutputRenderMilliseconds = std::max(smoothedOutputRenderMilliseconds, 0.0);
+	mBackendPlayout.maxOutputRenderMilliseconds = std::max(maxOutputRenderMilliseconds, 0.0);
 	mBackendPlayout.completedFrameIndex = completedFrameIndex;
 	mBackendPlayout.scheduledFrameIndex = scheduledFrameIndex;
 	mBackendPlayout.scheduledLeadFrames = scheduledLeadFrames;

apps/LoopThroughWithOpenGLCompositing/runtime/telemetry/HealthTelemetry.h

@@ -87,10 +87,16 @@ public:
 		std::string completionResult = "Unknown";
 		std::size_t readyQueueDepth = 0;
 		std::size_t readyQueueCapacity = 0;
+		std::size_t minReadyQueueDepth = 0;
+		std::size_t maxReadyQueueDepth = 0;
+		uint64_t readyQueueZeroDepthCount = 0;
 		uint64_t readyQueuePushedCount = 0;
 		uint64_t readyQueuePoppedCount = 0;
 		uint64_t readyQueueDroppedCount = 0;
 		uint64_t readyQueueUnderrunCount = 0;
+		double outputRenderMilliseconds = 0.0;
+		double smoothedOutputRenderMilliseconds = 0.0;
+		double maxOutputRenderMilliseconds = 0.0;
 		uint64_t completedFrameIndex = 0;
 		uint64_t scheduledFrameIndex = 0;
 		uint64_t scheduledLeadFrames = 0;
@@ -152,14 +158,18 @@ public:
 
 	void RecordBackendPlayoutHealth(const std::string& lifecycleState, const std::string& completionResult,
 		std::size_t readyQueueDepth, std::size_t readyQueueCapacity, uint64_t readyQueuePushedCount,
+		std::size_t minReadyQueueDepth, std::size_t maxReadyQueueDepth, uint64_t readyQueueZeroDepthCount,
 		uint64_t readyQueuePoppedCount, uint64_t readyQueueDroppedCount, uint64_t readyQueueUnderrunCount,
+		double outputRenderMilliseconds, double smoothedOutputRenderMilliseconds, double maxOutputRenderMilliseconds,
 		uint64_t completedFrameIndex, uint64_t scheduledFrameIndex, uint64_t scheduledLeadFrames,
 		uint64_t measuredLagFrames, uint64_t catchUpFrames, uint64_t lateStreak, uint64_t dropStreak,
 		uint64_t lateFrameCount, uint64_t droppedFrameCount, uint64_t flushedFrameCount,
 		bool degraded, const std::string& statusMessage);
 	bool TryRecordBackendPlayoutHealth(const std::string& lifecycleState, const std::string& completionResult,
 		std::size_t readyQueueDepth, std::size_t readyQueueCapacity, uint64_t readyQueuePushedCount,
+		std::size_t minReadyQueueDepth, std::size_t maxReadyQueueDepth, uint64_t readyQueueZeroDepthCount,
 		uint64_t readyQueuePoppedCount, uint64_t readyQueueDroppedCount, uint64_t readyQueueUnderrunCount,
+		double outputRenderMilliseconds, double smoothedOutputRenderMilliseconds, double maxOutputRenderMilliseconds,
 		uint64_t completedFrameIndex, uint64_t scheduledFrameIndex, uint64_t scheduledLeadFrames,
 		uint64_t measuredLagFrames, uint64_t catchUpFrames, uint64_t lateStreak, uint64_t dropStreak,
 		uint64_t lateFrameCount, uint64_t droppedFrameCount, uint64_t flushedFrameCount,

apps/LoopThroughWithOpenGLCompositing/videoio/VideoBackend.cpp

@@ -6,6 +6,7 @@
 #include "RenderEngine.h"
 #include "RuntimeEventDispatcher.h"
 
+#include <algorithm>
 #include <chrono>
 #include <cstring>
 #include <windows.h>
@@ -294,6 +295,13 @@ void VideoBackend::StartOutputCompletionWorker()
 	mPendingOutputCompletions.clear();
 	mReadyOutputQueue.Clear();
 	mNextReadyOutputFrameIndex = 0;
+	mHasReadyQueueDepthBaseline = false;
+	mMinReadyQueueDepth = 0;
+	mMaxReadyQueueDepth = 0;
+	mReadyQueueZeroDepthCount = 0;
+	mOutputRenderMilliseconds = 0.0;
+	mSmoothedOutputRenderMilliseconds = 0.0;
+	mMaxOutputRenderMilliseconds = 0.0;
 	mOutputCompletionWorkerStopping = false;
 	mOutputCompletionWorkerRunning = true;
 	mOutputCompletionWorker = std::thread(&VideoBackend::OutputCompletionWorkerMain, this);
@@ -347,7 +355,9 @@ void VideoBackend::ProcessOutputFrameCompletion(const VideoIOCompletion& complet
 {
 	RecordFramePacing(completion.result);
 	PublishOutputFrameCompleted(completion);
-	const VideoPlayoutRecoveryDecision recoveryDecision = AccountForCompletionResult(completion.result, mReadyOutputQueue.GetMetrics().depth);
+	const RenderOutputQueueMetrics initialQueueMetrics = mReadyOutputQueue.GetMetrics();
+	RecordReadyQueueDepthSample(initialQueueMetrics);
+	const VideoPlayoutRecoveryDecision recoveryDecision = AccountForCompletionResult(completion.result, initialQueueMetrics.depth);
 
 	FillReadyOutputQueue(completion);
 	if (!ScheduleReadyOutputFrame())
@@ -364,9 +374,15 @@ void VideoBackend::RecordBackendPlayoutHealth(VideoIOCompletionResult result, co
 		queueMetrics.depth,
 		queueMetrics.capacity,
 		queueMetrics.pushedCount,
+		mMinReadyQueueDepth,
+		mMaxReadyQueueDepth,
+		mReadyQueueZeroDepthCount,
 		queueMetrics.poppedCount,
 		queueMetrics.droppedCount,
 		queueMetrics.underrunCount,
+		mOutputRenderMilliseconds,
+		mSmoothedOutputRenderMilliseconds,
+		mMaxOutputRenderMilliseconds,
 		recoveryDecision.completedFrameIndex,
 		recoveryDecision.scheduledFrameIndex,
 		recoveryDecision.scheduledLeadFrames,
@@ -391,12 +407,14 @@ bool VideoBackend::FillReadyOutputQueue(const VideoIOCompletion& completion)
 			return filledAny;
 		filledAny = true;
 		metrics = mReadyOutputQueue.GetMetrics();
+		RecordReadyQueueDepthSample(metrics);
 	}
 	return true;
 }
 
 bool VideoBackend::RenderReadyOutputFrame(const VideoIOState& state, const VideoIOCompletion& completion)
 {
+	const auto renderStart = std::chrono::steady_clock::now();
 	VideoIOOutputFrame outputFrame;
 	if (!BeginOutputFrame(outputFrame))
 		return false;
@@ -409,9 +427,16 @@ bool VideoBackend::RenderReadyOutputFrame(const VideoIOState& state, const Video
 	if (!rendered)
 	{
 		ApplyLifecycleTransition(VideoBackendLifecycleState::Degraded, "Output frame render request failed; skipping schedule for this frame.");
+		const double renderMilliseconds = std::chrono::duration_cast<std::chrono::duration<double, std::milli>>(
+			std::chrono::steady_clock::now() - renderStart).count();
+		RecordOutputRenderDuration(renderMilliseconds);
 		return false;
 	}
 
+	const double renderMilliseconds = std::chrono::duration_cast<std::chrono::duration<double, std::milli>>(
+		std::chrono::steady_clock::now() - renderStart).count();
+	RecordOutputRenderDuration(renderMilliseconds);
+
 	RenderOutputFrame readyFrame;
 	readyFrame.frame = outputFrame;
 	readyFrame.frameIndex = ++mNextReadyOutputFrameIndex;
@@ -423,6 +448,7 @@ bool VideoBackend::ScheduleReadyOutputFrame()
 	RenderOutputFrame readyFrame;
 	if (!mReadyOutputQueue.TryPop(readyFrame))
 		return false;
+	RecordReadyQueueDepthSample(mReadyOutputQueue.GetMetrics());
 
 	if (!ScheduleOutputFrame(readyFrame.frame))
 		return false;
@@ -488,6 +514,37 @@ void VideoBackend::RecordFramePacing(VideoIOCompletionResult completionResult)
 	PublishTimingSample("VideoBackend", "smoothedCompletionInterval", mSmoothedCompletionIntervalMilliseconds, "ms");
 }
 
+void VideoBackend::RecordReadyQueueDepthSample(const RenderOutputQueueMetrics& metrics)
+{
+	if (!mHasReadyQueueDepthBaseline)
+	{
+		mHasReadyQueueDepthBaseline = true;
+		mMinReadyQueueDepth = metrics.depth;
+		mMaxReadyQueueDepth = metrics.depth;
+	}
+	else
+	{
+		mMinReadyQueueDepth = (std::min)(mMinReadyQueueDepth, metrics.depth);
+		mMaxReadyQueueDepth = (std::max)(mMaxReadyQueueDepth, metrics.depth);
+	}
+
+	if (metrics.depth == 0)
+		++mReadyQueueZeroDepthCount;
+}
+
+void VideoBackend::RecordOutputRenderDuration(double renderMilliseconds)
+{
+	mOutputRenderMilliseconds = (std::max)(renderMilliseconds, 0.0);
+	if (mSmoothedOutputRenderMilliseconds <= 0.0)
+		mSmoothedOutputRenderMilliseconds = mOutputRenderMilliseconds;
+	else
+		mSmoothedOutputRenderMilliseconds = mSmoothedOutputRenderMilliseconds * 0.9 + mOutputRenderMilliseconds * 0.1;
+	mMaxOutputRenderMilliseconds = (std::max)(mMaxOutputRenderMilliseconds, mOutputRenderMilliseconds);
+
+	PublishTimingSample("VideoBackend", "outputRender", mOutputRenderMilliseconds, "ms");
+	PublishTimingSample("VideoBackend", "smoothedOutputRender", mSmoothedOutputRenderMilliseconds, "ms");
+}
+
 bool VideoBackend::ApplyLifecycleTransition(VideoBackendLifecycleState state, const std::string& message)
 {
 	const VideoBackendLifecycleTransition transition = mLifecycle.TransitionTo(state, message);

apps/LoopThroughWithOpenGLCompositing/videoio/VideoBackend.h

@@ -75,6 +75,8 @@ private:
 	bool ScheduleReadyOutputFrame();
 	bool ScheduleBlackUnderrunFrame();
 	void RecordFramePacing(VideoIOCompletionResult completionResult);
+	void RecordReadyQueueDepthSample(const RenderOutputQueueMetrics& metrics);
+	void RecordOutputRenderDuration(double renderMilliseconds);
 	bool ApplyLifecycleTransition(VideoBackendLifecycleState state, const std::string& message);
 	bool ApplyLifecycleFailure(const std::string& message);
 	void PublishBackendStateChanged(const std::string& state, const std::string& message);
@@ -112,6 +114,13 @@ private:
 	double mCompletionIntervalMilliseconds = 0.0;
 	double mSmoothedCompletionIntervalMilliseconds = 0.0;
 	double mMaxCompletionIntervalMilliseconds = 0.0;
+	bool mHasReadyQueueDepthBaseline = false;
+	std::size_t mMinReadyQueueDepth = 0;
+	std::size_t mMaxReadyQueueDepth = 0;
+	uint64_t mReadyQueueZeroDepthCount = 0;
+	double mOutputRenderMilliseconds = 0.0;
+	double mSmoothedOutputRenderMilliseconds = 0.0;
+	double mMaxOutputRenderMilliseconds = 0.0;
 	uint64_t mLateFrameCount = 0;
 	uint64_t mDroppedFrameCount = 0;
 	uint64_t mFlushedFrameCount = 0;