From 7477da42a5bf2f22fe26c0db2525809e13a98b3b Mon Sep 17 00:00:00 2001 From: evgeny Date: Thu, 15 Oct 2026 17:26:09 +0200 Subject: [PATCH] Reduce Linux voice capture latency and verify device timing --- doc/linux_audio_recovery.md | 97 ++++++++++++++++++- tools/chatgui/CMakeLists.txt | 3 +- tools/chatgui/src/audio_device.cpp | 14 +++ tools/chatgui/src/audio_device.h | 1 + tools/chatgui/src/call_audio_engine.cpp | 4 +- tools/chatgui/src/radio_audio_engine.cpp | 1 + .../chatgui/tests/test_audio_diagnostics.cpp | 14 ++- tools/chatgui/tests/test_audio_recovery.cpp | 72 ++++++++++++-- tools/chatgui/tests/test_voice_audio_io.cpp | 89 ++++++++++++++++- tools/chatgui/transport/audio_diagnostics.cpp | 53 ++++++---- tools/chatgui/transport/miniaudio_impl.c | 32 +++++- 11 files changed, 342 insertions(+), 38 deletions(-) diff --git a/doc/linux_audio_recovery.md b/doc/linux_audio_recovery.md index e7e92856..76efd404 100644 --- a/doc/linux_audio_recovery.md +++ b/doc/linux_audio_recovery.md @@ -382,7 +382,7 @@ LeakSanitizer; LeakSanitizer запускается вне песочницы. M ThreadSanitizer. Изолированный интеграционный запуск: ```sh -python3 tools/chatgui/tests/run_pulse_recovery.py +dbus-run-session -- python3 tools/chatgui/tests/run_pulse_recovery.py ``` Итоговый прогон 2026-10-02: сборка `vibechat` успешна, CTest — 11/11, @@ -407,6 +407,101 @@ async-тесты исключены из дальнейших запусков. AEC в длительном реальном звонке этими проверками не подтверждены. Reference охватывает звук этого приложения на том же выходе, согласно выбранному контракту. +## Период Linux/PulseAudio и сравнительный замер + +`AudioDevice::requestLowLatency()` задаёт запрос 10 мс для capture звонка/рации. +Он применяется при каждом открытии, включая recovery и fallback. +Остальные backends сохраняют прежние параметры. +Общий и отдельный voice output сохраняют прежний период: запрос 10 мс +на проверенной системе не снизил измеренную задержку воспроизведения. +Кадры AEC/кодека остаются 20 мс; `noFixedSizedCallback` позволяет обслуживать +фактические порции backend без дополнительного накопления в miniaudio. + +Это запрос задержки, а не гарантия размера callback. PulseAudio согласует +`tlength`, `fragsize`, `minreq`, `maxlength`, `prebuf`; PipeWire также ограничивает +quantum и минимальные порции. `AudioDiag` при init выводит внутренний PCM-формат +и согласованные параметры в миллисекундах (`-1` — значение по умолчанию). +Пересчёт использует внутренние rate/channels/format, а не формат приложения. + +Секундные clock-отчёты содержат `latency_us`/`backend_us` и `block_us` в виде +`min/avg/max`. В задержку включены только измеренные timing snapshots; +`estimated_blocks`/`measured` позволяют отличить их отсутствие от нулевой задержки. +Для времени исполнения callback включать `call=trace`, для состояния AEC — +`aec=debug`. Логи агрегируются вне аппаратного callback. + +Ручной режим существующего стенда использует настоящие устройства и голосовые +workers, не сохраняет микрофонный PCM и не отправляет его по сети. Выход звонка +без удалённого собеседника обслуживается тишиной; акустическое подавление эха +этот режим не измеряет. Аргументы: capture frames, playback frames, секунды, +необязательный режим `call` (по умолчанию), `radio` или `output`, затем путь лога. +Ноль frames оставляет стандартный период backend; override применяется только +в тестовом executable, до настоящего `ma_device_init`. + +```sh +cmake --build tools/chatgui/build --target test_audio_recovery -j4 +tools/chatgui/build/test_audio_recovery --latency 960 0 60 > /tmp/audio-baseline.log 2>&1 +tools/chatgui/build/test_audio_recovery --latency 480 0 60 > /tmp/audio-capture10.log 2>&1 +tools/chatgui/build/test_audio_recovery --latency 960 480 60 > /tmp/audio-playback10.log 2>&1 +tools/chatgui/build/test_audio_recovery --latency 480 480 60 > /tmp/audio-both10.log 2>&1 +``` + +Запуски последовательные: несколько потоков могут менять общий quantum сервера. +Сравнивать одинаковые маршруты и нагрузку, отдельно от старта/остановки и после +стабилизации адаптивного PCM-резерва. Проверять backend latency, возраст первого +сэмпла перед готовым TX-кадром, очередь после mix, starvation, holes, потери PCM, +AEC reference и событий диагностики. Затем повторить baseline и проверить +выбранный вариант под нагрузкой. Меньший возраст PCM в capture callback сам по +себе не доказывает такой же выигрыш до кодирования: worker собирает кадры 20 мс. + +`test_voice_audio_io` дополнительно проверяет порции по 256 samples: порядок PCM, +временные метки, границы mute/PTT и позицию частичного playback. AEC проверяется +при разных порциях capture/reference (256/480 и 480/256) с противофазным stereo +reference. Очереди по-прежнему ограничены числом событий; уменьшение периода +не увеличивает их ёмкость в миллисекундах. + +Сравнение 2026-10-15 на встроенном HDA, PipeWire 1.6.2, 48 кГц. Каждый вариант +работал 60 секунд; таблица содержит средние по callback/кадрам после 45 секунд +прогрева (PCM-резерв к этому моменту уменьшился до одного блока). + +| Запрос capture / playback | Capture backend, мс | Первый сэмпл готового TX-кадра, мс | Playback backend, мс | PCM после mix, мс | +| --- | ---: | ---: | ---: | ---: | +| 20 мс / default 25 мс | 30,69 | 34,53 | 16,32 | 18,67 | +| 10 мс / default 25 мс | 16,02 | 29,79 | 16,15 | 18,67 | +| 20 мс / 10 мс | 31,51 | 34,97 | 18,09 | 24,00 | +| 10 мс / 10 мс | 16,13 | 29,66 | 18,46 | 24,00 | + +Изменение capture даёт около 14,7 мс на границе backend и около 4,7 мс перед +передачей полного кадра в голосовой стек. Для playback сервер согласовал +`tlength=16ms`, `minreq=5.333ms` при запросе 10 мс; callback уменьшился с 512 +до 256 samples, но выигрыша по задержке не получилось. Поэтому в рабочем коде +изменён только capture. Значения в столбцах не следует складывать как независимые +участки общей задержки: capture backend входит в возраст TX-кадра, а очередь после +mix снята уже после извлечения текущего выходного блока из очереди. + +В этих четырёх прогретых окнах не было потерь capture/reference PCM, выходного +starvation, backend underrun/overflow или потери событий диагностики. +Отдельные отсутствующие AEC references были и в baseline (4 кадра за окно), +и в остальных вариантах (4–5). Это существующее ограничение привязки reference, +а не проверка акустического качества. Первоначальный output starvation и +временное увеличение PCM-резерва учитываются отдельно от стабильного окна. + +Повтор baseline дал 30,76 мс capture backend и 34,99 мс возраста TX-кадра. +Двухминутный прогон выбранного capture 10 мс под нагрузкой четырёх CPU-процессов +дал после прогрева 15,81 и 28,55 мс соответственно; PCM после mix — 18,67 мс. +Потерь PCM, backend underrun/overflow и потери событий диагностики в этом окне +не было. За 75 секунд окна зарегистрировано 25 отсутствующих AEC references. +Отдельный минутный прогон рации: capture backend в среднем 15,48 мс, без потерь PCM. + +Сборка `vibechat` и 6 аудиотестов прошли. Изолированный интеграционный тест +подтвердил объединение выходных маршрутов и восстановление capture/playback после +перезапуска тестового PulseAudio. Запускать весь стенд через `dbus-run-session`, +чтобы имя его PulseAudio не конфликтовало с сервером пользовательской сессии. +В fixture перед `radio_audio_init` создаётся `radio_instance`, освобождаемый после +`radio_audio_destroy`; это исключает ложную ошибку регистрации mute callback. +Полный `check.sh` вне sandbox: 156/156, 9/9 proxy-интеграций, burst и load — PASS. +В sandbox сетевые тесты не проходят из-за запрета сокетов; этот запуск не является +проверкой сетевых регрессий. + ## Референсы Первичные исходники и документация просмотрены 2026-10-01; ссылки на master могут diff --git a/tools/chatgui/CMakeLists.txt b/tools/chatgui/CMakeLists.txt index 69e09f0b..ef3c1db5 100644 --- a/tools/chatgui/CMakeLists.txt +++ b/tools/chatgui/CMakeLists.txt @@ -620,7 +620,8 @@ if(CMAKE_SYSTEM_NAME STREQUAL "Linux") target_include_directories(test_audio_recovery PRIVATE ${UTUN_INCLUDE_DIRS}) target_link_libraries(test_audio_recovery PRIVATE ${QT_LIBS} utun_voice utun pthread dl) target_link_options(test_audio_recovery PRIVATE "-Wl,--wrap=ma_context_init" "-Wl,--wrap=ma_context_uninit" - "-Wl,--wrap=ma_device_init" "-Wl,--wrap=ma_device_start" "-Wl,--wrap=ma_device_uninit" "-Wl,--wrap=audio_context_failed") + "-Wl,--wrap=ma_device_init" "-Wl,--wrap=ma_device_start" "-Wl,--wrap=ma_device_uninit" "-Wl,--wrap=audio_context_failed" + "-Wl,--wrap=call_send_media") add_test(NAME test_audio_recovery COMMAND test_audio_recovery) set_tests_properties(test_audio_recovery PROPERTIES TIMEOUT 15) add_executable(test_radio_panel tests/test_radio_panel.cpp src/radiopanel.cpp src/radio_audio_engine.cpp diff --git a/tools/chatgui/src/audio_device.cpp b/tools/chatgui/src/audio_device.cpp index ec2918ee..9e61b1e2 100644 --- a/tools/chatgui/src/audio_device.cpp +++ b/tools/chatgui/src/audio_device.cpp @@ -12,6 +12,18 @@ extern "C" void audio_stream_log_route(ma_device* device, int capture); AudioDevice::AudioDevice() { m_clock.start(); } AudioDevice::~AudioDevice() { close(); } +void AudioDevice::requestLowLatency(ma_context* context, ma_device_config& config) { +#ifdef __linux__ + if (context && context->backend == ma_backend_pulseaudio) { + // Период I/O не зависит от размера кадра AEC/кодека; сервер согласует фактический буфер. + config.periodSizeInFrames = 0; + config.periodSizeInMilliseconds = 10; + } +#else + (void)context; (void)config; +#endif +} + bool AudioDevice::init(ma_context* context, ma_device_config config, const char* role, uint64_t session, Callback callback) { close(); m_role = role; @@ -22,6 +34,8 @@ bool AudioDevice::init(ma_context* context, ma_device_config config, const char* config.noFixedSizedCallback = MA_TRUE; // Аппаратные чанки не требуют скрытого накопителя miniaudio. config.notificationCallback = notification; config.pUserData = this; + DEBUG_INFO(DEBUG_CATEGORY_CALL, "audio: %s requested backend=%s rate=%u period_frames=%u period_ms=%u", + role, ma_get_backend_name(context->backend), config.sampleRate, config.periodSizeInFrames, config.periodSizeInMilliseconds); ma_result result = ma_device_init(context, &config, device); if (result != MA_SUCCESS) { DEBUG_ERROR(DEBUG_CATEGORY_CALL, "audio: %s init failed result=%d", role, result); diff --git a/tools/chatgui/src/audio_device.h b/tools/chatgui/src/audio_device.h index ea74ab46..88e2aa30 100644 --- a/tools/chatgui/src/audio_device.h +++ b/tools/chatgui/src/audio_device.h @@ -14,6 +14,7 @@ public: ~AudioDevice(); AudioDevice(const AudioDevice&) = delete; AudioDevice& operator=(const AudioDevice&) = delete; + static void requestLowLatency(ma_context* context, ma_device_config& config); bool init(ma_context* context, ma_device_config config, const char* role, uint64_t session, Callback callback); bool start(); void pause(); // GUI: завершает текущий callback, сохраняя backend stream и его физический route. diff --git a/tools/chatgui/src/call_audio_engine.cpp b/tools/chatgui/src/call_audio_engine.cpp index d4459c00..9f374940 100644 --- a/tools/chatgui/src/call_audio_engine.cpp +++ b/tools/chatgui/src/call_audio_engine.cpp @@ -59,8 +59,8 @@ bool CallAudioEngine::openCapture() { if (!context) return false; ma_device_config config = ma_device_config_init(ma_device_type_capture); config.capture.format = ma_format_s16; config.capture.channels = 1; config.sampleRate = CALL_AUDIO_SAMPLE_RATE; - config.periodSizeInMilliseconds = CALL_AUDIO_FRAME_MS; - DEBUG_INFO(DEBUG_CATEGORY_CALL, "CallAudio: capture requested period=%dms; actual period reported by device", CALL_AUDIO_FRAME_MS); + config.periodSizeInMilliseconds = 20; // Прежний запрос для остальных платформ/backends. + AudioDevice::requestLowLatency(context, config); ma_device_id id; bool selected = SoundManager::deviceId(m_captureId, &id); if (selected) config.capture.pDeviceID = &id; diff --git a/tools/chatgui/src/radio_audio_engine.cpp b/tools/chatgui/src/radio_audio_engine.cpp index 0d24625a..c2196d59 100644 --- a/tools/chatgui/src/radio_audio_engine.cpp +++ b/tools/chatgui/src/radio_audio_engine.cpp @@ -232,6 +232,7 @@ void RadioAudioEngine::openCapture() { config.capture.format = ma_format_s16; config.capture.channels = channels; config.sampleRate = RADIO_AUDIO_SAMPLE_RATE; + AudioDevice::requestLowLatency(context, config); auto callback = [this](const void* in, void*, unsigned int frames) { captureCallback(in, frames); }; ma_device_id id; bool selected = SoundManager::deviceId(m_captureId, &id); diff --git a/tools/chatgui/tests/test_audio_diagnostics.cpp b/tools/chatgui/tests/test_audio_diagnostics.cpp index ad475c53..2ead1d97 100644 --- a/tools/chatgui/tests/test_audio_diagnostics.cpp +++ b/tools/chatgui/tests/test_audio_diagnostics.cpp @@ -32,13 +32,16 @@ int main() { assert(capture.captureSequence == 1440 && capture.captureFrames == 1440 && capture.captureBlocks == 3); assert(capture.captureJumps == 1 && capture.captureMaxDelta == 4000 && capture.captureMinDelta == 0); assert(capture.captureMissing == 480 && capture.captureEstimated == 0); - assert(capture.captureMinLatency == 96000 && capture.captureMaxLatency == 100000); + assert(capture.captureLatency.low == 96000 && capture.captureLatency.high == 100000); + assert(capture.captureLatency.count == 3 && capture.captureLatency.average() == 97333); + assert(capture.captureBlock.low == 10000 && capture.captureBlock.high == 10000); report(devices, now(CLOCK_MONOTONIC), 1.0); timing.first_us = 1034000; timing.missing = 0; timing.measured = 0; audio_diag_capture_clock(nullptr, &timing); assert(take(e)); consume(e, devices); assert(capture.captureJumps == 0 && capture.captureMissing == 0 && capture.captureEstimated == 1); assert(capture.captureSequence == 1920 && capture.captureBlocks == 1 && capture.captureFrames == 480); + assert(capture.captureLatency.count == 0 && capture.captureBlock.count == 1); // Отсутствующий timestamp не превращается в измеренную нулевую задержку. audio_playback_timing output{30000, 1000, 1200, 48000, 1}; audio_diag_playback_clock(nullptr, &output); @@ -47,11 +50,12 @@ int main() { output.latency_us = 999999; output.measured = 0; audio_diag_playback_clock(nullptr, &output); while (take(e)) consume(e, devices); - assert(capture.playbackBlocks == 3 && capture.playbackFrames == 3120 && capture.playbackMeasured == 2); - assert(capture.playbackMinLatency == -1000 && capture.playbackMaxLatency == 30000); - assert(capture.playbackMaxBlock == 25000 && capture.playbackMaxConverter == 1000); + assert(capture.playbackBlocks == 3 && capture.playbackFrames == 3120 && capture.playbackLatency.count == 2); + assert(capture.playbackLatency.low == -1000 && capture.playbackLatency.high == 30000); + assert(capture.playbackBlock.high == 25000 && capture.playbackMaxConverter == 1000); + assert(capture.playbackLatency.average() == 14500 && capture.playbackBlock.low == 20000); report(devices, now(CLOCK_MONOTONIC), 1.0); - assert(capture.playbackBlocks == 0 && capture.playbackMeasured == 0 && capture.playbackMaxBlock == 0); + assert(capture.playbackBlocks == 0 && capture.playbackLatency.count == 0 && capture.playbackBlock.high == 0); std::vector workers; for (int p = 0; p < producers; ++p) workers.emplace_back([p, &done]() { for (int i = 0; i < perProducer; ++i) diff --git a/tools/chatgui/tests/test_audio_recovery.cpp b/tools/chatgui/tests/test_audio_recovery.cpp index 07705a60..df83e98b 100644 --- a/tools/chatgui/tests/test_audio_recovery.cpp +++ b/tools/chatgui/tests/test_audio_recovery.cpp @@ -1,4 +1,4 @@ -/* Настоящие null devices и Qt timers; linker wrappers инъецируют только сбои lifecycle. */ +/* Настоящие null/PulseAudio devices и Qt timers; wrappers инъецируют сбои либо параметры ручного замера. */ #include "../src/audio_device.h" #include "../src/call_audio_engine.h" #include "../src/radio_audio_engine.h" @@ -15,6 +15,7 @@ extern "C" { #include "utun_instance.h" #include "call/call_audio.h" #include "radio/radio_audio.h" +#include "radio/radio.h" #include "media_async/attachment_send.h" #include "u_async.h" #include "debug_config.h" @@ -27,6 +28,8 @@ static std::vector devices; static int starts, captureStarts, playbackStarts, contextStarts, failContexts; static bool failStart, failContext, failDevice; static bool pulseIntegration; +static bool latencyProbe; +static unsigned probeCaptureFrames, probePlaybackFrames; extern "C" UTUN_INSTANCE* gui_bridge_get_inst() { return &instance; } extern "C" int gui_bridge_is_uasync_ready() { return instance.ua != nullptr; } @@ -37,6 +40,10 @@ extern "C" ma_result __real_ma_device_init(ma_context*, const ma_device_config*, extern "C" ma_result __real_ma_device_start(ma_device*); extern "C" void __real_ma_device_uninit(ma_device*); extern "C" int __real_audio_context_failed(ma_context*); +extern "C" int __real_call_send_media(UTUN_INSTANCE*, uint64_t, const uint8_t*, int, const call_capture_time*); +extern "C" int __wrap_call_send_media(UTUN_INSTANCE* inst, uint64_t id, const uint8_t* data, int size, const call_capture_time* timing) { + return latencyProbe ? 0 : __real_call_send_media(inst, id, data, size, timing); +} extern "C" ma_result __wrap_ma_context_init(const ma_backend*, ma_uint32, const ma_context_config*, ma_context* context) { ++contextStarts; @@ -50,7 +57,14 @@ extern "C" void __wrap_ma_context_uninit(ma_context* context) { } extern "C" ma_result __wrap_ma_device_init(ma_context* context, const ma_device_config* config, ma_device* device) { if (failDevice) { failDevice = false; return MA_ERROR; } - ma_result result = __real_ma_device_init(context, config, device); + ma_device_config requested = *config; + if (latencyProbe) { + requested.periodSizeInMilliseconds = 0; + requested.periodSizeInFrames = config->deviceType == ma_device_type_capture ? probeCaptureFrames : probePlaybackFrames; + DEBUG_INFO(DEBUG_CATEGORY_CALL, "latency-probe: override type=%d period_frames=%u rate=%u", + config->deviceType, requested.periodSizeInFrames, requested.sampleRate); + } + ma_result result = __real_ma_device_init(context, &requested, device); if (result == MA_SUCCESS) { ++live[context]; devices.push_back(device); } return result; } @@ -79,12 +93,17 @@ extern "C" int __wrap_audio_context_failed(ma_context* context) { static void pump(int milliseconds) { QElapsedTimer timer; timer.start(); - while (timer.elapsed() < milliseconds) { QCoreApplication::processEvents(); QThread::msleep(1); } + while (timer.elapsed() < milliseconds) { + QCoreApplication::processEvents(); + if (latencyProbe && instance.ua) uasync_poll(instance.ua, 0); + QThread::msleep(1); + } } static void pulse_recovery(SoundManager* manager, const QString& control) { REQUIRE(manager->context()->backend == ma_backend_pulseaudio); instance.ua = uasync_create(); REQUIRE(instance.ua); + REQUIRE(radio_init_instance(&instance) == 0); REQUIRE(call_audio_init(&instance) == 0 && radio_audio_init(&instance) == 0); auto* call = CallAudioEngine::instance(); auto* radio = RadioAudioEngine::instance(); REQUIRE(call->start(42) == 0 && radio->start(7) == 0); @@ -130,18 +149,58 @@ static void pulse_recovery(SoundManager* manager, const QString& control) { qInfo("PulseAudio progress: capture=%d -> %dms playback=%llu -> %llu frames", duration, recorder.durationMs(), (unsigned long long)cursor, (unsigned long long)manager->pcmCursor(pcmId)); call->stop(); radio->stop(); recorder.stopRecording(); - call_audio_destroy(&instance); radio_audio_destroy(&instance); uasync_destroy(instance.ua, 0); instance.ua = nullptr; + call_audio_destroy(&instance); radio_audio_destroy(&instance); radio_destroy_instance(&instance); + uasync_destroy(instance.ua, 0); instance.ua = nullptr; manager->shutdown(); REQUIRE(devices.empty()); qInfo("real PulseAudio: capture/playback progress restored after server restart PASS"); } +/* Ручной стенд: настоящий I/O и voice workers, без сети и сохранения микрофонного PCM. + * --latency capture_frames playback_frames seconds [call|radio|output] [log]; 0 означает backend default. */ +static void measure_latency(SoundManager* manager, int seconds, const QString& kind) { + REQUIRE(manager->context()->backend == ma_backend_pulseaudio); + instance.ua = uasync_create(); REQUIRE(instance.ua); + REQUIRE(radio_init_instance(&instance) == 0); + REQUIRE(call_audio_init(&instance) == 0 && radio_audio_init(&instance) == 0); + auto* call = CallAudioEngine::instance(); auto* radio = RadioAudioEngine::instance(); + if (kind == "call") REQUIRE(call->start(42) == 0); + if (kind == "radio") REQUIRE(radio->start(7) == 0); + DEBUG_INFO(DEBUG_CATEGORY_CALL, "latency-probe: begin kind=%s seconds=%d capture_frames=%u playback_frames=%u", + qPrintable(kind), seconds, probeCaptureFrames, probePlaybackFrames); + pump(seconds * 1000); + DEBUG_INFO(DEBUG_CATEGORY_CALL, "latency-probe: end kind=%s", qPrintable(kind)); + call->stop(); radio->stop(); + call_audio_destroy(&instance); radio_audio_destroy(&instance); radio_destroy_instance(&instance); + uasync_destroy(instance.ua, 0); instance.ua = nullptr; + manager->shutdown(); REQUIRE(devices.empty()); +} + int main(int argc, char** argv) { QCoreApplication app(argc, argv); - pulseIntegration = argc == 3 && std::strcmp(argv[1], "--pulse-integration") == 0; + latencyProbe = argc >= 2 && std::strcmp(argv[1], "--latency") == 0; + int seconds = 0; + QString kind = argc >= 6 ? QString::fromLocal8Bit(argv[5]) : "call"; + if (latencyProbe) { + REQUIRE(argc >= 5 && argc <= 7); + bool captureOk, playbackOk, durationOk; + probeCaptureFrames = QString::fromLocal8Bit(argv[2]).toUInt(&captureOk); + probePlaybackFrames = QString::fromLocal8Bit(argv[3]).toUInt(&playbackOk); + seconds = QString::fromLocal8Bit(argv[4]).toInt(&durationOk); + REQUIRE(captureOk && playbackOk && durationOk && seconds > 0 && seconds <= 3600); + REQUIRE(probeCaptureFrames <= 4800 && probePlaybackFrames <= 4800); + REQUIRE(kind == "call" || kind == "radio" || kind == "output"); + } + pulseIntegration = latencyProbe || (argc == 3 && std::strcmp(argv[1], "--pulse-integration") == 0); debug_config_init(); debug_set_level(pulseIntegration ? DEBUG_LEVEL_INFO : DEBUG_LEVEL_WARN); + if (latencyProbe) { + debug_set_category_level(DEBUG_CATEGORY_CALL, DEBUG_LEVEL_TRACE); + debug_set_category_level(DEBUG_CATEGORY_AEC, DEBUG_LEVEL_DEBUG); + if (argc == 7) { debug_enable_file_output(argv[6], 1); REQUIRE(g_debug_config.file_output); } + } auto* manager = SoundManager::instance(); REQUIRE(manager->init() && manager->context()); + if (latencyProbe) { measure_latency(manager, seconds, kind); return 0; } if (pulseIntegration) { pulse_recovery(manager, QString::fromLocal8Bit(argv[2])); return 0; } ma_device_id id{}; auto outputs = manager->enumeratePlaybackDevices(); @@ -185,6 +244,7 @@ int main(int argc, char** argv) { REQUIRE(!request.pcm && !request.pcm_owner && !request.compressor); } instance.ua = uasync_create(); REQUIRE(instance.ua); + REQUIRE(radio_init_instance(&instance) == 0); REQUIRE(call_audio_init(&instance) == 0 && radio_audio_init(&instance) == 0); auto* call = CallAudioEngine::instance(); REQUIRE(call->start(42) == 0); @@ -285,7 +345,7 @@ int main(int argc, char** argv) { radio_audio_talk_begin(8); radio_audio_talk_end(8); radio_audio_stop(); REQUIRE(instance.ua->posted_tasks_head); // Завершение ядра освобождает ещё не выполненные PTT-задачи вместе с аргументами. - call_audio_destroy(&instance); radio_audio_destroy(&instance); + call_audio_destroy(&instance); radio_audio_destroy(&instance); radio_destroy_instance(&instance); uasync_destroy(instance.ua, 0); instance.ua = nullptr; manager->shutdown(); REQUIRE(devices.empty()); diff --git a/tools/chatgui/tests/test_voice_audio_io.cpp b/tools/chatgui/tests/test_voice_audio_io.cpp index 00273f36..00ec9b2e 100644 --- a/tools/chatgui/tests/test_voice_audio_io.cpp +++ b/tools/chatgui/tests/test_voice_audio_io.cpp @@ -31,10 +31,15 @@ static void capture_diagnostic(int, const char*, const char* message) { if (std::strstr(message, "voice-io: capture stalled")) idleReported = true; } static std::atomic output_position{0}, output_delay{0}; +static bool rampPlayback; +static unsigned playbackSource; extern "C" void radio_audio_playback_progress(uint64_t, uint64_t position, uint64_t delay) { output_delay = delay; output_position = position; } -extern "C" int call_audio_pull_pcm(uint64_t, int16_t* out, int count) { ++pulls; std::fill_n(out, count, 1000); return count; } +extern "C" int call_audio_pull_pcm(uint64_t, int16_t* out, int count) { + for (int i = 0; i < count; ++i) out[i] = rampPlayback ? int(playbackSource++ % 16000) - 8000 : 1000; + ++pulls; return count; +} extern "C" int radio_audio_pull_pcm(uint64_t, int16_t* out, int count) { ++pulls; for (int i = 0; i < count; ++i) out[i] = i % 2 ? 2000 : 1000; return count; } @@ -73,6 +78,85 @@ static void reset() { std::lock_guard lock(mutex); capture.clear(); transmitted.clear(); masks.clear(); captureTimes.clear(); captureResets = 0; talking = false; blocks = 0; } + +static void small_chunks() { + constexpr unsigned chunk = 256, total = chunk * 15; + std::array input{}; + for (unsigned i = 0; i < total; ++i) input[i] = int(i) - 1920; + for (auto kind : {VoiceAudioIo::Kind::Call, VoiceAudioIo::Kind::Radio}) { + reset(); + VoiceAudioIo voice; + REQUIRE(voice.start(kind, 45) && voice.startCapture(1, false)); + int64_t base = now_us(); + for (unsigned offset = 0; offset < total; offset += chunk) { + if (offset == chunk || offset == 5 * chunk) { + if (kind == VoiceAudioIo::Kind::Call) voice.setMuted(offset == chunk); + else voice.setPtt(offset == chunk); + } + voice.capture(input.data() + offset, chunk, base + int64_t(offset) * 1000000 / 48000, 1); + await([&] { std::lock_guard lock(mutex); return capture.size() >= (offset + chunk) / 960 * 960; }); + } + voice.stop(); + REQUIRE(captureResets == 0 && capture.size() == total && std::equal(capture.begin(), capture.end(), input.begin())); + if (kind == VoiceAudioIo::Kind::Call) { + for (unsigned i = 0; i < total; ++i) REQUIRE(masks[i] == (i >= chunk && i < 5 * chunk)); + for (size_t i = 0; i < captureTimes.size(); ++i) REQUIRE(std::abs(captureTimes[i] - base - int64_t(i) * 20000) <= 1); + } else { + REQUIRE(transmitted.size() == 4 * chunk && !talking); + REQUIRE(std::equal(transmitted.begin(), transmitted.end(), input.begin() + chunk)); + } + } + reset(); pulls = 0; output_position = 0; playbackSource = 0; rampPlayback = true; + VoiceAudioIo voice; + REQUIRE(voice.start(VoiceAudioIo::Kind::Call, 46)); + for (unsigned offset = 0; offset < total; offset += chunk) { + await([&] { return unsigned(pulls.load()) * 960 >= offset + chunk + 960; }); + float output[chunk * 2]{}; + voice.mix(output, chunk, now_us() + 10000, true); + await([&] { return output_position.load() == offset + chunk; }); + for (unsigned i = 0; i < chunk; ++i) { + float expected = (int(offset + i) - 8000) / 32768.0f; + REQUIRE(output[2*i] == expected && output[2*i+1] == expected); + } + } + voice.stop(); rampPlayback = false; + puts("256-frame chunks: PCM order, timestamps, mute/PTT boundaries and playback position PASS"); +} + +static void small_chunks_aec(unsigned captureChunk, unsigned renderChunk) { + reset(); + constexpr unsigned total = 240 * 960, warmup = 180 * 960; + std::vector input(total); + std::vector reference(total * 2); + uint32_t rng = 1234567; + double echoPower = 0, outputPower = 0; + for (unsigned i = 0; i < total; ++i) { + rng = rng * 1664525u + 1013904223u; + int16_t sample = (int16_t)((rng >> 18) - 8192); + reference[2*i] = sample / 32768.0f; reference[2*i+1] = -reference[2*i]; + input[i] = sample / 2; + if (i >= warmup) echoPower += double(input[i]) * input[i]; + } + VoiceAudioIo voice; + REQUIRE(voice.start(VoiceAudioIo::Kind::Call, 47) && voice.startCapture(1, true)); + int64_t base = now_us(); + unsigned rendered = 0; + for (unsigned offset = 0; offset < total; offset += captureChunk) { + unsigned count = std::min(captureChunk, total - offset); + while (rendered < offset + count) { + unsigned frames = std::min(renderChunk, total - rendered); + voice.reference(reference.data() + 2 * rendered, frames, base + int64_t(rendered) * 1000000 / 48000); + rendered += frames; + } + voice.capture(input.data() + offset, count, base + int64_t(offset) * 1000000 / 48000, 1); + await([&] { return unsigned(blocks.load()) == (offset + count) / 960; }); + } + voice.stop(); + REQUIRE(capture.size() == total && captureResets == 0); + for (unsigned i = warmup; i < total; ++i) outputPower += double(capture[i]) * capture[i]; + printf("small-chunk stereo AEC: capture=%u render=%u residual=%.6f\n", captureChunk, renderChunk, outputPower / echoPower); + REQUIRE(outputPower < echoPower * 0.1); +} int main() { debug_config_init(); debug_set_level(DEBUG_LEVEL_WARN); // Резерв уменьшается только при стабильной работе; крупный callback и starvation повышают минимум. @@ -213,5 +297,8 @@ int main() { for (size_t i = 180 * 960; i < capture.size(); ++i) outputPower += (double)capture[i] * capture[i]; printf("stereo reference residual ratio=%.6f\n", outputPower / echoPower); REQUIRE(outputPower < echoPower * 0.1); + small_chunks(); + small_chunks_aec(256, 480); + small_chunks_aec(480, 256); puts("voice workers: exact PTT/mute boundaries, short tail, independent RX, stereo AEC PASS"); } diff --git a/tools/chatgui/transport/audio_diagnostics.cpp b/tools/chatgui/transport/audio_diagnostics.cpp index ccefeea5..b8fd1bd7 100644 --- a/tools/chatgui/transport/audio_diagnostics.cpp +++ b/tools/chatgui/transport/audio_diagnostics.cpp @@ -96,6 +96,15 @@ struct Stage { long tid = 0; bool delayed = false; }; +struct TimingRange { + uint64_t count = 0; + int64_t low = 0, high = 0, sum = 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 / (int64_t)count : 0; } +}; struct Device { std::string label = "unlabelled"; uint64_t id = 0; @@ -103,9 +112,10 @@ struct Device { std::array faults{}; audio_capture_timing capture{}; uint64_t captureBlocks = 0, captureFrames = 0, captureSequence = 0, captureJumps = 0, captureMissing = 0, captureEstimated = 0; - int64_t captureMinDelta = 0, captureMaxDelta = 0, captureMinLatency = 0, captureMaxLatency = 0; - uint64_t playbackBlocks = 0, playbackFrames = 0, playbackMeasured = 0; - int64_t playbackMinLatency = 0, playbackMaxLatency = 0, playbackMaxConverter = 0, playbackMaxBlock = 0; + int64_t captureMinDelta = 0, captureMaxDelta = 0, captureMaxConverter = 0; + TimingRange captureLatency, captureBlock, playbackLatency, playbackBlock; + uint64_t playbackBlocks = 0, playbackFrames = 0; + int64_t playbackMaxConverter = 0; }; void consume(const Event& e, std::map& devices) { @@ -133,10 +143,11 @@ void consume(const Event& e, std::map& devices) { const int64_t delta = c.first_us - expected; if (!d.captureBlocks) { d.captureMinDelta = d.captureMaxDelta = delta; - d.captureMinLatency = d.captureMaxLatency = c.latency_us; } d.captureMinDelta = std::min(d.captureMinDelta, delta); d.captureMaxDelta = std::max(d.captureMaxDelta, delta); - d.captureMinLatency = std::min(d.captureMinLatency, c.latency_us); d.captureMaxLatency = std::max(d.captureMaxLatency, c.latency_us); + if (c.measured) d.captureLatency.add(c.latency_us); + if (c.rate) d.captureBlock.add(int64_t(c.frames) * 1000000 / c.rate); + d.captureMaxConverter = std::max(d.captureMaxConverter, c.converter_us); if (delta < -2000 || delta > 2000) { if (++d.captureJumps == 1) DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "AudioDiag: capture clock jump dev=%p role=%s sequence=%llu frames=%u rate=%u " @@ -154,14 +165,9 @@ void consume(const Event& e, std::map& devices) { } else if (e.kind == AUDIO_DIAG_PLAYBACK_CLOCK) { const auto& p = e.playback; ++d.playbackBlocks; d.playbackFrames += p.frames; - if (p.rate) d.playbackMaxBlock = std::max(d.playbackMaxBlock, int64_t(p.frames) * 1000000 / p.rate); + if (p.rate) d.playbackBlock.add(int64_t(p.frames) * 1000000 / p.rate); d.playbackMaxConverter = std::max(d.playbackMaxConverter, p.converter_us); - if (p.measured) { - if (!d.playbackMeasured) d.playbackMinLatency = d.playbackMaxLatency = p.latency_us; - ++d.playbackMeasured; - d.playbackMinLatency = std::min(d.playbackMinLatency, p.latency_us); - d.playbackMaxLatency = std::max(d.playbackMaxLatency, p.latency_us); - } + if (p.measured) d.playbackLatency.add(p.latency_us); } else if (e.kind == AUDIO_DIAG_LABEL) { d.label = e.text; d.id = uint64_t(e.value); DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: label dev=%p role=%s id=%016llx", (void*)e.device, e.text, (unsigned long long)d.id); @@ -209,22 +215,27 @@ void report(std::map& devices, uint64_t wall, double elapsed) for (auto& [key, d] : devices) { if (d.playbackBlocks) { DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "AudioDiag: playback clock dev=%p role=%s blocks=%llu frames=%llu measured=%llu " - "backend_us=%lld..%lld converter_max_us=%lld block_max_us=%lld", + "backend_us=%lld/%lld/%lld converter_max_us=%lld block_us=%lld/%lld/%lld", (void*)key, d.label.c_str(), (unsigned long long)d.playbackBlocks, (unsigned long long)d.playbackFrames, - (unsigned long long)d.playbackMeasured, (long long)d.playbackMinLatency, (long long)d.playbackMaxLatency, - (long long)d.playbackMaxConverter, (long long)d.playbackMaxBlock); - d.playbackBlocks = d.playbackFrames = d.playbackMeasured = 0; - d.playbackMinLatency = d.playbackMaxLatency = d.playbackMaxConverter = d.playbackMaxBlock = 0; + (unsigned long long)d.playbackLatency.count, (long long)d.playbackLatency.low, + (long long)d.playbackLatency.average(), (long long)d.playbackLatency.high, (long long)d.playbackMaxConverter, + (long long)d.playbackBlock.low, (long long)d.playbackBlock.average(), (long long)d.playbackBlock.high); + d.playbackBlocks = d.playbackFrames = 0; + d.playbackLatency = {}; d.playbackBlock = {}; d.playbackMaxConverter = 0; } if (d.captureBlocks) { DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "AudioDiag: capture clock dev=%p role=%s id=%016llx blocks=%llu frames=%llu " - "sequence=%llu delta_us=%lld..%lld latency_us=%lld..%lld jumps=%llu missing_frames=%llu estimated_blocks=%llu", + "sequence=%llu delta_us=%lld..%lld latency_us=%lld/%lld/%lld jumps=%llu missing_frames=%llu estimated_blocks=%llu " + "converter_max_us=%lld block_us=%lld/%lld/%lld", (void*)key, d.label.c_str(), (unsigned long long)d.id, (unsigned long long)d.captureBlocks, (unsigned long long)d.captureFrames, (unsigned long long)d.captureSequence, (long long)d.captureMinDelta, (long long)d.captureMaxDelta, - (long long)d.captureMinLatency, (long long)d.captureMaxLatency, - (unsigned long long)d.captureJumps, (unsigned long long)d.captureMissing, (unsigned long long)d.captureEstimated); + (long long)d.captureLatency.low, (long long)d.captureLatency.average(), (long long)d.captureLatency.high, + (unsigned long long)d.captureJumps, (unsigned long long)d.captureMissing, (unsigned long long)d.captureEstimated, + (long long)d.captureMaxConverter, (long long)d.captureBlock.low, + (long long)d.captureBlock.average(), (long long)d.captureBlock.high); d.captureBlocks = d.captureFrames = d.captureJumps = d.captureMissing = d.captureEstimated = 0; + d.captureLatency = {}; d.captureBlock = {}; d.captureMaxConverter = 0; } for (int i = 0; i < AUDIO_DIAG_STAGE_COUNT; ++i) { auto& s = d.stages[i]; @@ -300,7 +311,7 @@ void audio_diag_start(void) { DEBUG_ERROR(DEBUG_CATEGORY_CALL, "AudioDiag: reporter start failed: %s", e.what()); return; } - DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: started capacity=%llu check_interval=1s category=call normal=trace faults=warn; timestamps=CLOCK_MONOTONIC", + DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: started capacity=%llu check_interval=1s category=call normal=trace faults=warn; ranges=min/avg/max timestamps=CLOCK_MONOTONIC", (unsigned long long)kCapacity); } void audio_diag_stop(void) { diff --git a/tools/chatgui/transport/miniaudio_impl.c b/tools/chatgui/transport/miniaudio_impl.c index fc1a91c0..451b6745 100644 --- a/tools/chatgui/transport/miniaudio_impl.c +++ b/tools/chatgui/transport/miniaudio_impl.c @@ -30,6 +30,33 @@ static void audio_diag_pulse_started(ma_pa_stream* stream, void* userdata) { (void)stream; audio_diag_event(userdata, AUDIO_DIAG_BACKEND_STARTED, AUDIO_DIAG_WRITE, 1, 0); } + +static double audio_buffer_ms(ma_uint32 bytes, ma_uint32 bytes_per_second) { + return bytes == (ma_uint32)-1 ? -1.0 : (double)bytes * 1000 / bytes_per_second; +} + +/* После init, до запуска worker: размеры PA относятся к внутреннему PCM, не к client PCM. */ +static void audio_diag_pulse_buffer(ma_device* device, int capture) { + ma_pa_stream* stream = capture ? device->pulse.pStreamCapture : device->pulse.pStreamPlayback; + if (!stream) return; + const ma_pa_buffer_attr* attr = ((ma_pa_stream_get_buffer_attr_proc)device->pContext->pulse.pa_stream_get_buffer_attr)(stream); + ma_format format = capture ? device->capture.internalFormat : device->playback.internalFormat; + ma_uint32 channels = capture ? device->capture.internalChannels : device->playback.internalChannels; + ma_uint32 rate = capture ? device->capture.internalSampleRate : device->playback.internalSampleRate; + ma_uint32 bpf = ma_get_bytes_per_frame(format, channels); + if (!attr || !rate || !bpf) { + audio_diag_log(ma_device_get_log(device), MA_LOG_LEVEL_WARNING, "PulseAudio buffer snapshot unavailable"); + return; + } + ma_log_postf(ma_device_get_log(device), MA_LOG_LEVEL_INFO, + "[PulseAudio] dev=%p %s PCM format=%s channels=%u rate=%u bpf=%u\n", + (void*)device, capture ? "capture" : "playback", ma_get_format_name(format), channels, rate, bpf); + ma_log_postf(ma_device_get_log(device), MA_LOG_LEVEL_INFO, + "[PulseAudio] dev=%p %s buffer_ms tlength=%.3f fragsize=%.3f minreq=%.3f maxlength=%.3f prebuf=%.3f (-1=default)\n", + (void*)device, capture ? "capture" : "playback", audio_buffer_ms(attr->tlength, rate * bpf), + audio_buffer_ms(attr->fragsize, rate * bpf), audio_buffer_ms(attr->minreq, rate * bpf), + audio_buffer_ms(attr->maxlength, rate * bpf), audio_buffer_ms(attr->prebuf, rate * bpf)); +} #endif /* Только init-поток: backend-callbacks остаются короткими наблюдателями. */ @@ -37,7 +64,10 @@ static void audio_diag_pulse_init(void* device) { #ifdef MA_SUPPORT_PULSEAUDIO ma_device* dev = (ma_device*)device; ma_pa_stream_set_suspended_callback_proc underflow, overflow, started; - if (dev->pContext->backend != ma_backend_pulseaudio || !dev->pulse.pStreamPlayback) return; + if (dev->pContext->backend != ma_backend_pulseaudio) return; + audio_diag_pulse_buffer(dev, 1); + audio_diag_pulse_buffer(dev, 0); + if (!dev->pulse.pStreamPlayback) return; #ifndef MA_NO_RUNTIME_LINKING underflow = (ma_pa_stream_set_suspended_callback_proc)dlsym(dev->pContext->pulse.pulseSO, "pa_stream_set_underflow_callback"); overflow = (ma_pa_stream_set_suspended_callback_proc)dlsym(dev->pContext->pulse.pulseSO, "pa_stream_set_overflow_callback");