Report desktop voice queue and capture processing latency

tools/chatgui/src/voice_audio_io.cpp

@@ -17,6 +17,17 @@ static int64_t voice_time_us() {
     return std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now().time_since_epoch()).count();
 }
 
+/* Только владелец worker: накопление чисел без лога на каждый кадр. */
+struct VoiceLatencyRange {
+    int64_t low = 0, high = 0, sum = 0;
+    unsigned count = 0;
+    void add(int64_t value) {
+        if (!count) low = high = value;
+        low = std::min(low, value); high = std::max(high, value); sum += value; ++count;
+    }
+    int64_t average() const { return count ? sum / count : 0; }
+};
+
 VoiceAudioIo::~VoiceAudioIo() { stop(); }
 
 bool VoiceAudioIo::start(Kind kind, uint64_t session) {
@@ -141,11 +152,12 @@ void VoiceAudioIo::mix(float* stereo, unsigned frames, int64_t firstTimeUs, bool
         ++m_playPosition;
         ++consumed;
     }
-    if (consumed) {
-        PlaybackProgress progress{epoch, m_playCurrent.position + m_playPosition,
-                                  firstTimeUs + (int64_t)consumed * 1000000 / 48000, measured};
-        if (!m_playProgress.push(progress)) m_progressDropped.fetch_add(1, std::memory_order_relaxed);
-    }
+    // size() — приблизительный снимок; учитываем также остаток уже извлечённого блока.
+    unsigned remaining = m_playCurrent.epoch == epoch ? 960 - m_playPosition : 0;
+    PlaybackProgress progress{epoch, m_playCurrent.position + m_playPosition,
+                              firstTimeUs + (int64_t)consumed * 1000000 / 48000, measured,
+                              consumed, frames - consumed, unsigned(m_playback.size() * 960) + remaining};
+    if (!m_playProgress.push(progress)) m_progressDropped.fetch_add(1, std::memory_order_relaxed);
     m_wake.notify_all();
 }
 
@@ -153,6 +165,8 @@ void VoiceAudioIo::playbackLoop() {
     uint64_t epoch = m_playEpoch.load();
     uint64_t position = 0;
     int64_t lastClockReport = 0;
+    VoiceLatencyRange queueUs, pullUs;
+    unsigned missing = 0;
     call_clock_snapshot clock{};
     if (m_kind == Kind::Call && call_audio_get_clock(m_session, voice_time_us(), &clock) != 0)
         DEBUG_WARN(DEBUG_CATEGORY_CALL, "voice-io: call clock unavailable session=%llu", (unsigned long long)m_session);
@@ -172,6 +186,9 @@ void VoiceAudioIo::playbackLoop() {
         PlaybackProgress progress{};
         for (unsigned count = 0; count < 32 && m_playProgress.pop(progress); ++count) {
             if (progress.epoch != epoch) continue;
+            queueUs.add(int64_t(progress.queuedFrames) * 1000000 / 48000);
+            missing += progress.missing;
+            if (!progress.consumed) continue;
             int64_t now = voice_time_us(), remaining = progress.endTimeUs - now;
             if (m_kind == Kind::Call)
                 call_audio_playback_progress(m_session, clock.epoch, progress.position, progress.endTimeUs, now, progress.measured);
@@ -183,6 +200,13 @@ void VoiceAudioIo::playbackLoop() {
         int64_t reportTime = voice_time_us();
         if (m_kind == Kind::Call && reportTime - lastClockReport >= 1000000) {
             lastClockReport = reportTime;
+            if (queueUs.count || pullUs.count)
+                DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "voice-io: playback latency session=%llu samples=%u pulls=%u "
+                            "pcm_after_mix_us=%lld/%lld/%lld pull_us=%lld/%lld/%lld missing_samples=%u queue_estimate=1",
+                            (unsigned long long)m_session, queueUs.count, pullUs.count,
+                            (long long)queueUs.low, (long long)queueUs.average(), (long long)queueUs.high,
+                            (long long)pullUs.low, (long long)pullUs.average(), (long long)pullUs.high, missing);
+            queueUs = {}; pullUs = {}; missing = 0;
             call_clock_snapshot snapshot{};
             if (call_audio_get_clock(m_session, reportTime, &snapshot) == 0)
                 DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "audio clock session=%llu epoch=%llu source=%llu played=%llu written=%llu "
@@ -193,11 +217,13 @@ void VoiceAudioIo::playbackLoop() {
         }
         if (m_playback.size() < 2) {
             Playback block{}; block.epoch = epoch; block.position = position;
+            int64_t pullAt = voice_time_us();
             if (m_kind == Kind::Call) {
                 int16_t mono[960]{};
                 int count = std::clamp(call_audio_pull_pcm(m_session, mono, 960), 0, 960);
                 for (int i = 0; i < count; ++i) block.pcm[2*i] = block.pcm[2*i+1] = mono[i];
             } else radio_audio_pull_pcm(m_session, block.pcm, 1920);
+            pullUs.add(voice_time_us() - pullAt);
             position += 960;
             if (!m_playback.push(block)) DEBUG_WARN(DEBUG_CATEGORY_CALL, "voice-io: playback queue contention");
         } else {
@@ -238,6 +264,7 @@ void VoiceAudioIo::captureLoop() {
     double rawEnergy = 0, cleanEnergy = 0, referenceEnergy = 0;
     float rawPeak = 0, cleanPeak = 0, referencePeak = 0;
     unsigned signalFrames = 0, aecFrames = 0;
+    VoiceLatencyRange captureAge, prepareUs, feedUs;
     bool muted = false;
     auto applyMarker = [&](EventKind kind, bool value) {
         if (kind == EventKind::Mute) muted = value;
@@ -306,7 +333,12 @@ void VoiceAudioIo::captureLoop() {
             if (mark < markerCount) applyMarker(markers[mark].kind, markers[mark].value);
             begin = end;
         }
-        if (m_kind == Kind::Call && frames == 960) call_audio_feed_prepared_pcm(m_session, cleaned, muteMask, frameTime);
+        if (m_kind == Kind::Call && frames == 960) {
+            int64_t now = voice_time_us();
+            captureAge.add(now - frameTime); // Возраст первого сэмпла; включает длительность самого блока.
+            call_audio_feed_prepared_pcm(m_session, cleaned, muteMask, frameTime);
+            feedUs.add(voice_time_us() - now);
+        }
         filled = 0; markerCount = 0;
     };
     // Отчёт работает и при отсутствии PCM, иначе длительный провал захвата невидим.
@@ -321,6 +353,15 @@ void VoiceAudioIo::captureLoop() {
                 DEBUG_WARN(DEBUG_CATEGORY_CALL, "voice-io: capture stalled session=%llu no_pcm=%.1fms queue=%zu",
                            (unsigned long long)m_session, (now - lastCapture) / 1000.0, m_captureEvents.size());
             maxQueueAge = 0;
+            if (captureAge.count) {
+                DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "voice-io: capture latency session=%llu frames=%u "
+                            "first_sample_age_us=%lld/%lld/%lld prepare_us=%lld/%lld/%lld feed_us=%lld/%lld/%lld",
+                            (unsigned long long)m_session, captureAge.count,
+                            (long long)captureAge.low, (long long)captureAge.average(), (long long)captureAge.high,
+                            (long long)prepareUs.low, (long long)prepareUs.average(), (long long)prepareUs.high,
+                            (long long)feedUs.low, (long long)feedUs.average(), (long long)feedUs.high);
+                captureAge = {}; prepareUs = {}; feedUs = {};
+            }
             if (captureClock.initialized) {
                 DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "voice-io: capture clock session=%llu sequence=%llu phase_us=%.1f "
                             "error_max_us=%lld adjustment_max_us=%lld", (unsigned long long)m_session,
@@ -396,6 +437,7 @@ void VoiceAudioIo::captureLoop() {
             memcpy(raw + filled * m_channels, event.pcm + offset * m_channels, take * m_channels * sizeof(int16_t));
             filled += take; offset += take;
             if (filled != 960) continue;
+            int64_t prepareAt = voice_time_us();
             memcpy(cleaned, raw, 960 * m_channels * sizeof(int16_t));
             consumeReference();
             bool available = aec && alignReference();
@@ -424,6 +466,7 @@ void VoiceAudioIo::captureLoop() {
                 }
             }
             referenceAvailable = available;
+            prepareUs.add(voice_time_us() - prepareAt);
             deliver(960);
         }
 

tools/chatgui/src/voice_audio_io.h

@@ -41,7 +41,12 @@ private:
         int16_t pcm[1920]{};
     };
     struct Playback { uint64_t epoch = 0, position = 0; int16_t pcm[1920]{}; };
-    struct PlaybackProgress { uint64_t epoch = 0, position = 0; int64_t endTimeUs = 0; bool measured = false; };
+    struct PlaybackProgress {
+        uint64_t epoch = 0, position = 0;
+        int64_t endTimeUs = 0;
+        bool measured = false;
+        unsigned consumed = 0, missing = 0, queuedFrames = 0;
+    };
     AudioEventQueue<Event, 32> m_captureEvents, m_references;
     AudioEventQueue<Playback, 12> m_playback;
     AudioEventQueue<PlaybackProgress, 32> m_playProgress;