chatgui: measure duplex audio stalls and record SM call evidence

doc/tasks.md

@@ -43,6 +43,15 @@
     причина редких аудиоколлбэков пока не установлена. Добавить измерения интервалов
     и длительности callback, кадров capture/playback и сводку CALL_STATS; сравнить
     сетевые задержки после подключения ПК к 5ГГц или кабелю.
+    Повторный звонок `b2a423ed2d36ed83` (01:25:31–01:27:39): DIRECT сохраняется,
+    RTT 2–3мс; в начале на SM gap tone длится 1.8–2.0с примерно каждые 6с.
+    На Qt частота callback падает вплоть до 4/с, входящий PCM продолжает приходить:
+    буфер 65→465→1465→2079мс за 3с, затем растёт до нескольких секунд, dropped=0.
+    Локализовано прекращение обслуживания duplex-аудио Qt; ожидание backend и
+    задержка обработки PCM пока не разделены. Часы SM отстают от Qt примерно на 1.24с.
+    Добавлена диагностика backend/устройств, времени между callback и длительности
+    capture/playback, фактической частоты callback и PCM кадров за интервал.
+    Счётчики сбрасываются до старта устройства; нужна повторная запись с новой сборкой.
 
 [ ] **Гонка invite-файла в test_chat_join_e2e** — `wait_file()` проверяет только
     существование файла, а `wf()` создаёт его до записи. Читатель иногда получает

tools/chatgui/src/call_audio_engine.cpp

@@ -11,6 +11,7 @@ extern "C" {
 }
 
 #include <QTimer>
+#include <algorithm>
 #include <cstring>
 
 static CallAudioEngine* g_callAudioEngine = nullptr;
@@ -102,6 +103,12 @@ int CallAudioEngine::initDevice() {
             return -1;
         }
     }
+    DEBUG_INFO(DEBUG_CATEGORY_DEBUG, "CallAudio: device backend=%s rate=%u capture='%s' rate=%u period=%u playback='%s' rate=%u period=%u",
+               ma_get_backend_name(ctx->backend), m_device->sampleRate,
+               m_device->capture.name, m_device->capture.internalSampleRate, m_device->capture.internalPeriodSizeInFrames,
+               m_device->playback.name, m_device->playback.internalSampleRate, m_device->playback.internalPeriodSizeInFrames);
+    m_capturePos = 0;
+    m_dbg = {};
     if (ma_device_start(m_device) != MA_SUCCESS) {
         DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "CallAudio: device start failed");
         ma_device_uninit(m_device);
@@ -109,7 +116,6 @@ int CallAudioEngine::initDevice() {
         return -1;
     }
     m_deviceStarted = true;
-    m_capturePos = 0;
     return 0;
 }
 
@@ -164,25 +170,19 @@ void CallAudioEngine::teardownDevice() {
 void CallAudioEngine::dataCallback(const void* in, void* out, unsigned int frames) {
     const int16_t* in16 = (const int16_t*)in;
     int16_t* out16 = (int16_t*)out;
+    uint64_t startTb = get_time_tb();
+    uint64_t idleTb = m_dbg.lastEndTb ? startTb - m_dbg.lastEndTb : 0;
+    if (!m_dbg.lastReportTb) m_dbg.lastReportTb = startTb;
 
     /* диагностика (DEBUG_CATEGORY_DEBUG): фактические параметры miniaudio-коллбэка */
-    if (m_dbgFrames == 0) {
-        m_dbgFrames = frames;
+    if (m_dbg.frames != frames) {
+        m_dbg.frames = frames;
         DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CallAudio: callback frames=%u in=%s out=%s",
                     frames, in16 ? "yes" : "no", out16 ? "yes" : "no");
     }
-    m_dbgCbCount++;
-    {
-        uint64_t now = get_time_tb();
-        if (m_dbgLastTb == 0) m_dbgLastTb = now;
-        else if (now - m_dbgLastTb >= 10000) {
-            DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG, "CallAudio: cb=%u/s frames=%u", m_dbgCbCount, frames);
-            m_dbgCbCount = 0;
-            m_dbgLastTb = now;
-        }
-    }
 
     /* захват: копим 960 samples → encode+send (сервисный слой). mute → тишина. */
+    uint64_t captureStartTb = get_time_tb();
     if (in16) {
         bool muted = m_muted.load();
         for (unsigned int i = 0; i < frames; i++) {
@@ -193,9 +193,40 @@ void CallAudioEngine::dataCallback(const void* in, void* out, unsigned int frame
             }
         }
     }
+    uint64_t captureEndTb = get_time_tb();
 
     /* воспроизведение: финальный PCM из сервисного слоя (jitter+stretch+тоны) */
     int n = call_audio_pull_pcm(m_callId.load(), out16, (int)frames);
     if (n < (int)frames)
         std::memset(out16 + n, 0, (size_t)(frames - n) * sizeof(int16_t));
+    uint64_t endTb = get_time_tb();
+    uint64_t captureTb = captureEndTb - captureStartTb;
+    uint64_t playbackTb = endTb - captureEndTb;
+    m_dbg.callbacks++;
+    m_dbg.captureFrames += in16 ? frames : 0;
+    m_dbg.playbackFrames += out16 ? frames : 0;
+    m_dbg.maxIdleTb = std::max(m_dbg.maxIdleTb, idleTb);
+    m_dbg.maxCaptureTb = std::max(m_dbg.maxCaptureTb, captureTb);
+    m_dbg.maxPlaybackTb = std::max(m_dbg.maxPlaybackTb, playbackTb);
+    if (idleTb > 500 || endTb - startTb > 200) {
+        DEBUG_WARN(DEBUG_CATEGORY_DEBUG, "CallAudio: stall call=%016llx idle=%.1fms work=%.1fms capture=%.1fms playback=%.1fms frames=%u",
+                   (unsigned long long)m_callId.load(), idleTb / 10.0, (endTb - startTb) / 10.0,
+                   captureTb / 10.0, playbackTb / 10.0, frames);
+    }
+    uint64_t elapsedTb = endTb - m_dbg.lastReportTb;
+    if (elapsedTb >= 10000) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_DEBUG,
+                    "CallAudio: interval=%.1fms cb=%.1f/s capture=%.0f/s playback=%.0f/s max_idle=%.1fms max_capture=%.1fms max_playback=%.1fms",
+                    elapsedTb / 10.0, m_dbg.callbacks * 10000.0 / elapsedTb,
+                    m_dbg.captureFrames * 10000.0 / elapsedTb, m_dbg.playbackFrames * 10000.0 / elapsedTb,
+                    m_dbg.maxIdleTb / 10.0, m_dbg.maxCaptureTb / 10.0, m_dbg.maxPlaybackTb / 10.0);
+        m_dbg.callbacks = 0;
+        m_dbg.captureFrames = 0;
+        m_dbg.playbackFrames = 0;
+        m_dbg.maxIdleTb = 0;
+        m_dbg.maxCaptureTb = 0;
+        m_dbg.maxPlaybackTb = 0;
+        m_dbg.lastReportTb = endTb;
+    }
+    m_dbg.lastEndTb = get_time_tb();
 }

tools/chatgui/src/call_audio_engine.h

@@ -60,8 +60,16 @@ private:
     std::vector<int16_t> m_captureBuf;   /* 960 samples, аудио-поток */
     int                  m_capturePos = 0;
 
-    /* диагностика (DEBUG_CATEGORY_DEBUG): фактические параметры miniaudio-коллбэка */
-    unsigned int m_dbgFrames = 0;
-    uint32_t     m_dbgCbCount = 0;
-    uint64_t     m_dbgLastTb = 0;
+    /* Только аудио-поток; сброс до ma_device_start. Время в 0.1мс. */
+    struct {
+        unsigned int frames = 0;
+        uint32_t callbacks = 0;
+        uint64_t captureFrames = 0;
+        uint64_t playbackFrames = 0;
+        uint64_t lastReportTb = 0;
+        uint64_t lastEndTb = 0;
+        uint64_t maxIdleTb = 0;
+        uint64_t maxCaptureTb = 0;
+        uint64_t maxPlaybackTb = 0;
+    } m_dbg;
 };