From dba813e8c5aee4867ef4d1e630c48fdb2b1d626a Mon Sep 17 00:00:00 2001 From: evgeny Date: Thu, 15 Oct 2026 11:36:58 +0200 Subject: [PATCH] Report desktop voice queue and capture processing latency --- tools/chatgui/src/voice_audio_io.cpp | 55 +++++++++++++++++++++++++--- tools/chatgui/src/voice_audio_io.h | 7 +++- 2 files changed, 55 insertions(+), 7 deletions(-) diff --git a/tools/chatgui/src/voice_audio_io.cpp b/tools/chatgui/src/voice_audio_io.cpp index 799c35d6..9ed7008a 100644 --- a/tools/chatgui/src/voice_audio_io.cpp +++ b/tools/chatgui/src/voice_audio_io.cpp @@ -17,6 +17,17 @@ static int64_t voice_time_us() { return std::chrono::duration_cast(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); } diff --git a/tools/chatgui/src/voice_audio_io.h b/tools/chatgui/src/voice_audio_io.h index 7a96ce16..736bcf91 100644 --- a/tools/chatgui/src/voice_audio_io.h +++ b/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 m_captureEvents, m_references; AudioEventQueue m_playback; AudioEventQueue m_playProgress;