fix(stats): improve presentation pacing observability

nativelib/src/main/cpp/CMakeLists.txt

@@ -86,6 +86,8 @@ set(SOURCE_FILES
     usb_ddk_poller.cpp
     native_render.cpp
     presentation_scheduler.cpp
+    presentation_diagnostics.cpp
+    rolling_frame_rate.cpp
     gl_post_processor.cpp
     sdl_gamecontrollerdb.cpp
 )

nativelib/src/main/cpp/native_render.cpp

@@ -31,6 +31,26 @@
 #undef LOG_TAG
 #define LOG_TAG "NativeRender"
 
+namespace {
+constexpr int64_t kNanosecondsPerMillisecond = 1000000LL;
+constexpr int64_t kVsyncSampleIntervalNs = 250 * kNanosecondsPerMillisecond;
+constexpr int64_t kHostPacedStatsLogIntervalFrames = 600;
+
+std::atomic<uint64_t> g_vsyncSampleGeneration{0};
+std::atomic<int64_t> g_observedVsyncTimestampNs{0};
+std::atomic<int64_t> g_observedVsyncPeriodNs{0};
+std::atomic<int64_t> g_vsyncSampleRequestFailures{0};
+
+void OnVSyncSample(long long timestamp, void* data) {
+    const uint64_t generation = static_cast<uint64_t>(
+        reinterpret_cast<uintptr_t>(data));
+    if (generation == g_vsyncSampleGeneration.load(std::memory_order_acquire)) {
+        g_observedVsyncTimestampNs.store(
+            static_cast<int64_t>(timestamp), std::memory_order_release);
+    }
+}
+} // namespace
+
 // RenderOutputBufferAtTime 是 API 12+ 的函数，旧设备或不完整运行时可能不存在
 // 通过 dlsym 动态加载，避免硬依赖
 typedef OH_AVErrCode (*PFN_RenderOutputBufferAtTime)(OH_AVCodec*, uint32_t, int64_t);
@@ -149,6 +169,12 @@ void NativeRender::InitNativeVSync() {
     const char* name = "moonlight_render";
     nativeVSync_ = OH_NativeVSync_Create(name, strlen(name));
     if (nativeVSync_ != nullptr) {
+        nativeVsyncGeneration_ =
+            g_vsyncSampleGeneration.fetch_add(1, std::memory_order_acq_rel) + 1;
+        g_observedVsyncTimestampNs.store(0, std::memory_order_release);
+        g_observedVsyncPeriodNs.store(0, std::memory_order_release);
+        g_vsyncSampleRequestFailures.store(0, std::memory_order_relaxed);
+        lastVsyncSampleRequestNs_.store(0, std::memory_order_relaxed);
         OH_LOG_INFO(LOG_APP, "NativeVSync created successfully");
     } else {
         OH_LOG_WARN(LOG_APP, "Failed to create NativeVSync");
@@ -161,6 +187,10 @@ void NativeRender::ReleaseNativeVSync() {
         return;
     }
 
+    g_vsyncSampleGeneration.fetch_add(1, std::memory_order_acq_rel);
+    nativeVsyncGeneration_ = 0;
+    g_observedVsyncTimestampNs.store(0, std::memory_order_release);
+    g_observedVsyncPeriodNs.store(0, std::memory_order_release);
     OH_NativeVSync_Destroy(nativeVSync_);
     nativeVSync_ = nullptr;
     OH_LOG_INFO(LOG_APP, "NativeVSync destroyed");
@@ -219,7 +249,7 @@ void NativeRender::SetVsyncEnabled(bool enable) {
     bool wasEnabled = vsyncEnabled_.exchange(enable);
     if (wasEnabled != enable) {
         {
-            std::lock_guard<std::mutex> lock(presentationMutex_);
+            std::unique_lock<std::mutex> lock(presentationMutex_);
             ResetPresentationClockLocked();
             ResetPresentationStatsLocked();
         }
@@ -352,6 +382,38 @@ void NativeRender::ApplyFrameRateRange() {
     }
 }
 
+void NativeRender::RequestVSyncSample(int64_t nowNs) {
+    int64_t previousRequestNs =
+        lastVsyncSampleRequestNs_.load(std::memory_order_relaxed);
+    if (previousRequestNs > 0 &&
+        nowNs - previousRequestNs < kVsyncSampleIntervalNs) {
+        return;
+    }
+    if (!lastVsyncSampleRequestNs_.compare_exchange_strong(
+            previousRequestNs, nowNs, std::memory_order_relaxed)) {
+        return;
+    }
+
+    std::lock_guard<std::mutex> lock(nativeVsyncMutex_);
+    if (nativeVSync_ == nullptr || nativeVsyncGeneration_ == 0) {
+        return;
+    }
+
+    long long periodNs = 0;
+    if (OH_NativeVSync_GetPeriod(nativeVSync_, &periodNs) == 0 &&
+        periodNs > 0) {
+        g_observedVsyncPeriodNs.store(
+            static_cast<int64_t>(periodNs), std::memory_order_release);
+    }
+
+    const int result = OH_NativeVSync_RequestFrame(
+        nativeVSync_, OnVSyncSample,
+        reinterpret_cast<void*>(static_cast<uintptr_t>(nativeVsyncGeneration_)));
+    if (result != 0) {
+        g_vsyncSampleRequestFailures.fetch_add(1, std::memory_order_relaxed);
+    }
+}
+
 // =============================================================================
 // PTS presentation clocks
 // =============================================================================
@@ -376,8 +438,11 @@ void NativeRender::ResetPresentationStatsLocked() {
     precisePhaseShiftCount_ = 0;
     preciseRebufferCount_ = 0;
     preciseResyncCount_ = 0;
+    preciseQueueFullCount_ = 0;
+    preciseWaitForDrainCount_ = 0;
     preciseApiFailureCount_ = 0;
     preciseMaxTargetLeadNs_ = 0;
+    presentationDiagnostics_.Reset();
 }
 
 void NativeRender::ResetPresentationClock() {
@@ -487,49 +552,78 @@ NativeRender::FrameSubmitResult NativeRender::SubmitFrame(const DecodedFrame& fr
             }
         } else {
             const int64_t decodedAtNs = GetMonotonicTimeNs();
-            PresentationPlan plan;
-            {
-                std::lock_guard<std::mutex> lock(presentationMutex_);
-                plan = ptsScheduler_.PlanFrame(frame.ptsUs, decodedAtNs);
-                if (plan.action == PresentationAction::SCHEDULE) {
-                    preciseScheduledCount_++;
-                } else {
-                    preciseDroppedCount_++;
-                }
-                if (plan.latenessNs > 0) preciseLateCount_++;
-                if (plan.event == PresentationEvent::CATCH_UP) {
-                    preciseCatchUpCount_++;
-                }
-                if (plan.event == PresentationEvent::PHASE_SHIFT) precisePhaseShiftCount_++;
-                if (plan.event == PresentationEvent::REBUFFER) preciseRebufferCount_++;
-                if (plan.event == PresentationEvent::DISCONTINUITY ||
-                    plan.event == PresentationEvent::DUPLICATE_PTS) {
-                    preciseResyncCount_++;
-                }
-                if (plan.action == PresentationAction::SCHEDULE) {
-                    preciseMaxTargetLeadNs_ = std::max(
-                        preciseMaxTargetLeadNs_, plan.targetTimeNs - decodedAtNs);
-                }
+            RequestVSyncSample(decodedAtNs);
+            const int64_t observedVsyncNs =
+                g_observedVsyncTimestampNs.load(std::memory_order_acquire);
+            const int64_t observedVsyncPeriodNs =
+                g_observedVsyncPeriodNs.load(std::memory_order_acquire);
+            const PresentationVsyncTiming vsyncTiming = {
+                observedVsyncNs, observedVsyncPeriodNs};
+
+            // Keep planning and timed submission ordered even if a codec emits
+            // output callbacks concurrently.
+            std::unique_lock<std::mutex> lock(presentationMutex_);
+            const PresentationPlan plan = ptsScheduler_.PlanFrame(
+                frame.ptsUs, decodedAtNs, vsyncTiming);
+            if (plan.action == PresentationAction::SCHEDULE) {
+                preciseScheduledCount_++;
+            } else {
+                preciseDroppedCount_++;
+            }
+            if (plan.latenessNs > 0) preciseLateCount_++;
+            if (plan.event == PresentationEvent::CATCH_UP) preciseCatchUpCount_++;
+            if (plan.event == PresentationEvent::PHASE_SHIFT) precisePhaseShiftCount_++;
+            if (plan.event == PresentationEvent::REBUFFER) preciseRebufferCount_++;
+            if (plan.event == PresentationEvent::DISCONTINUITY ||
+                plan.event == PresentationEvent::DUPLICATE_PTS) {
+                preciseResyncCount_++;
+            }
+            if (plan.event == PresentationEvent::QUEUE_FULL) preciseQueueFullCount_++;
+            if (plan.event == PresentationEvent::WAIT_FOR_DRAIN) {
+                preciseWaitForDrainCount_++;
+            }
+            if (plan.action == PresentationAction::SCHEDULE) {
+                preciseMaxTargetLeadNs_ = std::max(
+                    preciseMaxTargetLeadNs_, plan.targetTimeNs - decodedAtNs);
+                presentationDiagnostics_.Record(
+                    plan.targetTimeNs, decodedAtNs,
+                    observedVsyncNs, observedVsyncPeriodNs);
+            }
 
-                const int64_t totalFrames = preciseScheduledCount_ + preciseDroppedCount_;
-                if (totalFrames % 6000 == 0) {
-                    OH_LOG_INFO(LOG_APP,
-                        "Host-paced stats: frames=%{public}lld, scheduled=%{public}lld, dropped=%{public}lld, late=%{public}lld, catchUp=%{public}lld, phaseShift=%{public}lld, rebuffer=%{public}lld, resync=%{public}lld, apiFailure=%{public}lld, lead=%{public}lldus, maxLead=%{public}lldus",
-                        static_cast<long long>(totalFrames),
-                        static_cast<long long>(preciseScheduledCount_),
-                        static_cast<long long>(preciseDroppedCount_),
-                        static_cast<long long>(preciseLateCount_),
-                        static_cast<long long>(preciseCatchUpCount_),
-                        static_cast<long long>(precisePhaseShiftCount_),
-                        static_cast<long long>(preciseRebufferCount_),
-                        static_cast<long long>(preciseResyncCount_),
-                        static_cast<long long>(preciseApiFailureCount_),
-                        static_cast<long long>(ptsScheduler_.GetInitialLeadNs() / 1000),
-                        static_cast<long long>(preciseMaxTargetLeadNs_ / 1000));
-                }
+            const int64_t totalFrames = preciseScheduledCount_ + preciseDroppedCount_;
+            if (totalFrames % kHostPacedStatsLogIntervalFrames == 0) {
+                const PresentationTimingStats& timing =
+                    presentationDiagnostics_.GetStats();
+                OH_LOG_INFO(LOG_APP,
+                    "Host-paced stats: frames=%{public}lld, scheduled=%{public}lld, dropped=%{public}lld, late=%{public}lld, catchUp=%{public}lld, phaseShift=%{public}lld, rebuffer=%{public}lld, resync=%{public}lld, queueFull=%{public}lld, waitDrain=%{public}lld, apiFailure=%{public}lld, lead=%{public}lldus, maxLead=%{public}lldus, sameSlot=%{public}lld, slotRegression=%{public}lld, targetRegression=%{public}lld, maxRegression=%{public}lldus, maxQueueSlots=%{public}lld, vsyncPeriod=%{public}lldus, vsyncAge=%{public}lldus, vsyncSampleFailure=%{public}lld",
+                    static_cast<long long>(totalFrames),
+                    static_cast<long long>(preciseScheduledCount_),
+                    static_cast<long long>(preciseDroppedCount_),
+                    static_cast<long long>(preciseLateCount_),
+                    static_cast<long long>(preciseCatchUpCount_),
+                    static_cast<long long>(precisePhaseShiftCount_),
+                    static_cast<long long>(preciseRebufferCount_),
+                    static_cast<long long>(preciseResyncCount_),
+                    static_cast<long long>(preciseQueueFullCount_),
+                    static_cast<long long>(preciseWaitForDrainCount_),
+                    static_cast<long long>(preciseApiFailureCount_),
+                    static_cast<long long>(ptsScheduler_.GetInitialLeadNs() / 1000),
+                    static_cast<long long>(preciseMaxTargetLeadNs_ / 1000),
+                    static_cast<long long>(timing.sameVsyncSlotCount),
+                    static_cast<long long>(timing.vsyncSlotRegressionCount),
+                    static_cast<long long>(timing.targetRegressionCount),
+                    static_cast<long long>(timing.maxTargetRegressionNs / 1000),
+                    static_cast<long long>(timing.maxQueueDepthSlots),
+                    static_cast<long long>(observedVsyncPeriodNs / 1000),
+                    static_cast<long long>(observedVsyncNs > 0
+                        ? std::max<int64_t>(0, decodedAtNs - observedVsyncNs) / 1000
+                        : 0),
+                    static_cast<long long>(g_vsyncSampleRequestFailures.load(
+                        std::memory_order_relaxed)));
             }
 
             if (plan.action == PresentationAction::DROP) {
+                lock.unlock();
                 renderResult = freeFrame();
             } else {
                 renderResult = renderAtTime(
@@ -538,10 +632,7 @@ NativeRender::FrameSubmitResult NativeRender::SubmitFrame(const DecodedFrame& fr
                     bufferConsumed = true;
                     framePresented = true;
                 } else {
-                    {
-                        std::lock_guard<std::mutex> lock(presentationMutex_);
-                        preciseApiFailureCount_++;
-                    }
+                    preciseApiFailureCount_++;
                     OH_LOG_WARN(LOG_APP,
                         "Host-paced render failed: %{public}d, pts=%{public}lld, targetNs=%{public}lld; falling back",
                         renderResult, static_cast<long long>(frame.ptsUs),

nativelib/src/main/cpp/native_render.h

@@ -30,6 +30,7 @@
 #include <multimedia/player_framework/native_avcodec_videodecoder.h>
 #include <hilog/log.h>
 
+#include "presentation_diagnostics.h"
 #include "presentation_scheduler.h"
 
 #include <cstdint>
@@ -125,6 +126,9 @@ class NativeRender {
 
     // 应用帧率范围（通过 NativeVSync，API 20+）
     void ApplyFrameRateRange();
+
+    // 请求低频率的只读 VSync 时间样本，用于呈现诊断
+    void RequestVSyncSample(int64_t nowNs);
 
     // 应用 NativeWindow 帧率（Surface buffer queue 级别，API 12+）
     void ApplyNativeWindowFrameRate();
@@ -162,6 +166,7 @@ class NativeRender {
     // separate clocks so switching decoder modes cannot perturb PTS cadence.
     mutable std::mutex presentationMutex_;
     PtsPresentationScheduler ptsScheduler_;
+    PresentationDiagnostics presentationDiagnostics_;
 
     // Legacy VSync clock, kept isolated from the host-paced scheduler.
     int64_t estimatedOffsetNs_ = 0;  // 平滑后的 (本地 - host) 偏移均值(纳秒)
@@ -180,12 +185,16 @@ class NativeRender {
     int64_t precisePhaseShiftCount_ = 0;
     int64_t preciseRebufferCount_ = 0;
     int64_t preciseResyncCount_ = 0;
+    int64_t preciseQueueFullCount_ = 0;
+    int64_t preciseWaitForDrainCount_ = 0;
     int64_t preciseApiFailureCount_ = 0;
     int64_t preciseMaxTargetLeadNs_ = 0;
 
     // NativeVSync（用于设置期望帧率范围，API 20+）
     std::mutex nativeVsyncMutex_;
     OH_NativeVSync* nativeVSync_ = nullptr;
+    uint64_t nativeVsyncGeneration_ = 0;
+    std::atomic<int64_t> lastVsyncSampleRequestNs_{0};
 
 };
 

nativelib/src/main/cpp/presentation_diagnostics.cpp

@@ -0,0 +1,60 @@
+#include "presentation_diagnostics.h"
+
+#include <algorithm>
+
+void PresentationDiagnostics::Reset() {
+    stats_ = {};
+    lastTargetTimeNs_ = 0;
+}
+
+int64_t PresentationDiagnostics::NormalizeVsyncAnchor(
+        int64_t observedVsyncNs, int64_t nowNs, int64_t vsyncPeriodNs) {
+    if (nowNs <= observedVsyncNs) {
+        return observedVsyncNs;
+    }
+    return observedVsyncNs +
+        ((nowNs - observedVsyncNs) / vsyncPeriodNs) * vsyncPeriodNs;
+}
+
+int64_t PresentationDiagnostics::VsyncSlotAtOrAfter(
+        int64_t targetTimeNs, int64_t anchorNs, int64_t vsyncPeriodNs) {
+    const int64_t deltaNs = targetTimeNs - anchorNs;
+    const int64_t slotOffset = deltaNs >= 0
+        ? (deltaNs + vsyncPeriodNs - 1) / vsyncPeriodNs
+        : deltaNs / vsyncPeriodNs;
+    return anchorNs + slotOffset * vsyncPeriodNs;
+}
+
+void PresentationDiagnostics::Record(
+        int64_t targetTimeNs, int64_t nowNs,
+        int64_t observedVsyncNs, int64_t vsyncPeriodNs) {
+    if (lastTargetTimeNs_ > 0 && targetTimeNs < lastTargetTimeNs_) {
+        const int64_t regressionNs = lastTargetTimeNs_ - targetTimeNs;
+        stats_.targetRegressionCount++;
+        stats_.maxTargetRegressionNs = std::max(
+            stats_.maxTargetRegressionNs, regressionNs);
+    }
+
+    if (observedVsyncNs > 0 && vsyncPeriodNs > 0) {
+        const int64_t anchorNs = NormalizeVsyncAnchor(
+            observedVsyncNs, nowNs, vsyncPeriodNs);
+        const int64_t currentSlotNs = VsyncSlotAtOrAfter(
+            targetTimeNs, anchorNs, vsyncPeriodNs);
+        if (lastTargetTimeNs_ > 0) {
+            const int64_t previousSlotNs = VsyncSlotAtOrAfter(
+                lastTargetTimeNs_, anchorNs, vsyncPeriodNs);
+            if (currentSlotNs == previousSlotNs) {
+                stats_.sameVsyncSlotCount++;
+            } else if (currentSlotNs < previousSlotNs) {
+                stats_.vsyncSlotRegressionCount++;
+            }
+        }
+
+        const int64_t queueDepthSlots = std::max<int64_t>(
+            0, (currentSlotNs - anchorNs) / vsyncPeriodNs);
+        stats_.maxQueueDepthSlots = std::max(
+            stats_.maxQueueDepthSlots, queueDepthSlots);
+    }
+
+    lastTargetTimeNs_ = targetTimeNs;
+}

nativelib/src/main/cpp/presentation_diagnostics.h

@@ -0,0 +1,32 @@
+#ifndef PRESENTATION_DIAGNOSTICS_H
+#define PRESENTATION_DIAGNOSTICS_H
+
+#include <cstdint>
+
+struct PresentationTimingStats {
+    int64_t targetRegressionCount = 0;
+    int64_t maxTargetRegressionNs = 0;
+    int64_t sameVsyncSlotCount = 0;
+    int64_t vsyncSlotRegressionCount = 0;
+    int64_t maxQueueDepthSlots = 0;
+};
+
+class PresentationDiagnostics {
+public:
+    void Reset();
+    void Record(int64_t targetTimeNs, int64_t nowNs,
+                int64_t observedVsyncNs, int64_t vsyncPeriodNs);
+
+    const PresentationTimingStats& GetStats() const { return stats_; }
+
+private:
+    static int64_t NormalizeVsyncAnchor(
+        int64_t observedVsyncNs, int64_t nowNs, int64_t vsyncPeriodNs);
+    static int64_t VsyncSlotAtOrAfter(
+        int64_t targetTimeNs, int64_t anchorNs, int64_t vsyncPeriodNs);
+
+    PresentationTimingStats stats_;
+    int64_t lastTargetTimeNs_ = 0;
+};
+
+#endif // PRESENTATION_DIAGNOSTICS_H