diff --git a/doc/call_video.txt b/doc/call_video.txt index b3698cc0..3701759f 100644 --- a/doc/call_video.txt +++ b/doc/call_video.txt @@ -867,3 +867,56 @@ test_call_video проверяет сочетания PPS flags/extra header bit отказ при выходе адреса за CTB и при отключённом picture output. test_call_video_gpu меняет PPS на настоящем HEVC IDR и проверяет полный pipeline с decoder, а также отказ несовместимой стартовой пробы. Общий verifier используется и на Android: для HEVC обновить обе стороны звонка. Буферизация не меняется. + +Аудит восстановления после коротких пауз, 19.10.2026 +Новое требование: сохранять последовательность encoded кадров, быстро декодировать пришедший +burst и плавно догонять показом. Короткая пауза не должна вызывать пропуск входного P-кадра, +ожидание следующего KEY или перескок на более свежее изображение. +Текущая реализация этому требованию не соответствует; в этой итерации добавлена диагностика, +алгоритм буферизации/показа и действующие ограничения не изменены. + +1. Router сохраняет порядок, при заполнении RX port приостанавливает доставку/ACK и возобновляет + её после pull. RX port имеет 8 кадров/4MiB; это предел ёмкости, не обязательный стартовый запас. +2. Desktop декодирует последовательно, держит до двух готовых изображений. Android ограничивает + decoder inputs + готовые outputs восемью кадрами, готовые outputs — двумя. Подача/декодирование + в итоге ограничиваются освобождением готовых кадров, отдельного быстрого drain всего burst нет. +3. Playout имеет номинальное расписание 1.04x. При срыве поставки срок двигается по received_us, + но позднее выполнение worker само по себе срок не переносит. DROP_LATE отбрасывает показ при + отставании от audio PTS больше 50мс; DROP_SCHEDULE пропускает изображение, если следующий + кадр тоже уже пора показать. Оба пути работают после decode, codec references сохраняются. +4. Desktop GUI хранит последнее выбранное изображение вместо FIFO. Пока queued notification + не исполнено, новые publishImage заменяют предыдущее. Это ещё один пропуск показа после + decode. Прежний ui_wait_us считался от последней замены, поэтому мог скрыть паузу GUI; + диагностика теперь отдельно считает ожидание notification, возраст последней замены и overwritten. +5. Потеря до decoder тоже возможна. TX mailbox освобождает всю пачку после попытки передачи, + включая кадр с результатом busy=0 и оставшийся хвост. Producer получает запрос KEY, а не retry. + Admission закрывается при receive_busy или достижении предела долга; transport также имеет + предел 32 кадров/500мс PTS/2MiB и deadline головы 2с. Отказ готовому encoded кадру разрывает + цепочку references; последующие P-кадры ждут KEY. Это отличается от DROP_LATE/SCHEDULE. + +Контрольная симуляция настоящего call_video_playout (90 кадров, 30fps, пауза 200мс): +пауза доставки при непрерывном аудио — показано 86, late=4; +пауза CPU при непрерывном аудио — показано 84, late=5, schedule=1; +пауза CPU и удержание audio PTS с последующим догоном 1.1x — показано 77, late=12, schedule=1. +Шаг poll в этих сценариях 1мс; при шаге 15.625мс последний сценарий даёт 74 показа и 15 late. +Шаг 15.625мс — параметр модели, не утверждение о фактическом Windows timer resolution. +Даже при идеальном исполнении 1.04x убирает дополнительные 200мс примерно за 5с. +Существующий test_backlog явно требует DROP_LATE и DROP_SCHEDULE после паузы 102мс; +его успешность подтверждает старую политику, а не новое требование сохранения кадров. + +Для нового поведения нужны согласованные изменения: +- encoded FIFO с переносом backpressure до producer и сохранением неотправленного хвоста; +- последовательная подача decoder без ожидания срока показа, пока хватает выходной ёмкости; +- упорядоченный показ с адаптивным ускорением по накопленной длительности, без late/schedule + пропусков при короткой паузе. Возобновление от первого сохранённого кадра, без мгновенного burst; +- сохранение выбранного кадра до фактического потребления GUI/render, вместо overwrite последним; +- временное A/V-отставание во время восстановления либо согласованная задержка аудио и видео. + Сохранить все кадры после 200мс паузы и одновременно требовать A/V <=50мс невозможно. +Предел короткой паузы, память и политика длительного переполнения должны задаваться явно. +Обычный догон не должен запрашивать KEY или сбрасывать decoder. + +Windows-диагностика: AudioDiag теперь работает через тот же bounded reporter, что и Linux. +При call=debug WASAPI queue показывает padding и stream latency отдельно, callback/write — +время исполнения/интервалы; video RX worker показывает decode и опоздание пробуждения. +video late drop содержит точные PTS/AV/возраст первого позднего кадра за окно, playout — +диапазоны всех late кадров. Измерения не корректируют Windows callback-estimate аудиочасы. diff --git a/doc/chat_call_arch.md b/doc/chat_call_arch.md index 32c36958..9f326284 100644 --- a/doc/chat_call_arch.md +++ b/doc/chat_call_arch.md @@ -219,6 +219,27 @@ Backend публикует только числовой снимок в огр длительность pull и недостающие сэмплы. Это очередь приложения, отдельно от backend. - `AudioDiag: playback clock`: latency backend, задержка конвертера/cache и максимальный размер backend-порции в микросекундах. При measured=0 нулевые границы не означают нулевую задержку. +- Windows `AudioDiag: WASAPI queue`: текущий padding shared-mode, отдельный stream latency, + converter/cache, размер callback и незавершённого mapped buffer. Диапазоны — min/avg/max в мкс; + `padding_samples=0` означает отсутствие пригодного замера, а не пустую очередь. + Снимок снимается перед заполнением client PCM; запись и форматирование выполняет reporter. + `AudioDiag: audio timing` для стадий `callback`/`write` при `call=debug` показывает интервалы + callback и время блокирующей передачи в WASAPI. HRESULT ошибок и потери диагностической очереди логируются. + Снимки только наблюдают: Windows-аудиочасы остаются `callback-estimate` (`measured=0`). +- `video late drop`: первый пропущенный за секунду кадр, его PTS, audio PTS, отставание, + возраст от приёма до решения и абсолютные сроки. `video playout` агрегирует `late_av_us` + и `late_rx_age_us` всех поздних кадров; порог пропуска остаётся 50мс. +- Desktop `video RX worker`: число декодированных кадров, максимальное время декодирования, + возраст кадра после декодирования и опоздание пробуждения worker после sleep. Снимок аудио + содержит `audio_measured`, PTS и позиции played/written. Все эти строки относятся к `call=debug`; + `video=trace` для этой диагностики не требуется. +- `video GUI delivery`: выбранные изображения, доставленные в GUI, число замен до исполнения + уведомления и максимальные ожидание уведомления/промежуток доставки. В `stage=publish` + `ui_wait_us` считается от постановки уведомления, `selected_age_us` — от последней замены кадра. + Малый возраст последнего кадра сам по себе не исключает паузу GUI и замену предыдущих кадров. +- `video port TX frames released` и `TX mailbox busy` показывают фактическую потерю готовых + encoded кадров при отказе отправки. Это отдельный путь от пропуска уже декодированного показа; + диагностика сохраняет действующее поведение отказа и запроса KEY. - `call audio TX timing`: ожидание g_mtx, обработка/кодирование под ним, ожидание posted task; post включает ожидание lock при выполнении задачи, его разрешение 100мкс. На Android этот же замер обработки включает программный AEC, на desktop AEC уже выполнен в capture worker. diff --git a/lib/miniaudio.h b/lib/miniaudio.h index bbc84668..75059c4e 100644 --- a/lib/miniaudio.h +++ b/lib/miniaudio.h @@ -24963,6 +24963,7 @@ static ma_result ma_device_write__wasapi(ma_device* pDevice, const void* pFrames { ma_result result = MA_SUCCESS; ma_uint32 totalFramesProcessed = 0; + MA_DIAGNOSTIC_EVENT(pDevice, AUDIO_DIAG_ENTER, AUDIO_DIAG_WRITE, frameCount, pDevice->wasapi.mappedBufferPlaybackLen); /* Keep writing to the device until it's stopped or we've consumed all of our input. */ while (ma_device_get_state(pDevice) == ma_device_state_started && totalFramesProcessed < frameCount) { @@ -25049,6 +25050,7 @@ static ma_result ma_device_write__wasapi(ma_device* pDevice, const void* pFrames *pFramesWritten = totalFramesProcessed; } + MA_DIAGNOSTIC_EVENT(pDevice, AUDIO_DIAG_LEAVE, AUDIO_DIAG_WRITE, totalFramesProcessed, result); return result; } diff --git a/src/call/call_video_playout.c b/src/call/call_video_playout.c index 74e46daa..c8116231 100644 --- a/src/call/call_video_playout.c +++ b/src/call/call_video_playout.c @@ -43,12 +43,15 @@ static void report(struct call_video_playout *p, int64_t now) { DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video playout call=%llu interval_us=%lld shown=%u drop_late=%u drop_schedule=%u drop_order=%u " "cadence_us=%lld..%lld gap_pts_us=%lld gap_rx_us=%lld gap_dispatch_us=%lld " - "av_us=%lld..%lld dispatch_max_us=%lld data_shift_us=%lld audio_wait=%u clock_wait=%u", + "av_us=%lld..%lld dispatch_max_us=%lld data_shift_us=%lld audio_wait=%u clock_wait=%u " + "late_av_us=%lld..%lld late_rx_age_us=%lld..%lld", (unsigned long long)p->call_id, (long long)(now - p->report_us), p->shown, p->late, p->skipped, p->order, (long long)(p->interval_min == INT64_MAX ? 0 : p->interval_min), (long long)p->interval_max, (long long)p->gap_pts, (long long)p->gap_received, (long long)p->gap_dispatch, (long long)(p->shown ? p->av_min : 0), (long long)(p->shown ? p->av_max : 0), - (long long)p->dispatch_max, (long long)p->data_shift, p->audio_wait, p->clock_wait); + (long long)p->dispatch_max, (long long)p->data_shift, p->audio_wait, p->clock_wait, + (long long)(p->late ? p->late_av_min : 0), (long long)(p->late ? p->late_av_max : 0), + (long long)(p->late ? p->late_age_min : 0), (long long)(p->late ? p->late_age_max : 0)); p->report_us = now; p->shown = p->late = p->skipped = p->order = p->audio_wait = p->clock_wait = 0; p->interval_min = p->av_min = INT64_MAX; p->av_max = INT64_MIN; p->interval_max = p->dispatch_max = p->data_shift = 0; @@ -88,7 +91,21 @@ enum call_video_playout_action call_video_playout_poll(struct call_video_playout } p->last_pts = f->pts_us; p->last_deadline = deadline; p->anchored = 1; if (available > planned) p->data_shift += available - planned; - if (action == CALL_VIDEO_PLAYOUT_DROP_LATE) p->late++; + if (action == CALL_VIDEO_PLAYOUT_DROP_LATE) { + int64_t age = now - f->received_us; + if (!p->late) { + p->late_av_min = p->late_av_max = av; p->late_age_min = p->late_age_max = age; + DEBUG_WARN(DEBUG_CATEGORY_CALL, "video late drop call=%llu pts=%lld audio_pts=%lld av_us=%lld limit_us=%d " + "rx_age_us=%lld received_us=%lld mono_us=%lld planned_us=%lld deadline_us=%lld", + (unsigned long long)p->call_id, (long long)f->pts_us, (long long)audio, (long long)av, VIDEO_LATE_US, + (long long)age, (long long)f->received_us, (long long)now, (long long)planned, (long long)deadline); + } + if (av < p->late_av_min) p->late_av_min = av; + if (av > p->late_av_max) p->late_av_max = av; + if (age < p->late_age_min) p->late_age_min = age; + if (age > p->late_age_max) p->late_age_max = age; + p->late++; + } else if (action == CALL_VIDEO_PLAYOUT_DROP_SCHEDULE) p->skipped++; else { if (now - deadline > p->dispatch_max) p->dispatch_max = now - deadline; diff --git a/src/call/call_video_playout.h b/src/call/call_video_playout.h index fecebd3f..78609970 100644 --- a/src/call/call_video_playout.h +++ b/src/call/call_video_playout.h @@ -22,6 +22,7 @@ struct call_video_playout { int64_t last_pts, last_deadline, deadline_us; int64_t report_us, last_show_us, interval_min, interval_max, av_min, av_max, dispatch_max, data_shift; int64_t last_show_pts, last_received, gap_pts, gap_received, gap_dispatch; + int64_t late_av_min, late_av_max, late_age_min, late_age_max; // A/V и возраст от RX до пропуска за окно сводки. unsigned shown, late, skipped, order, audio_wait, clock_wait; }; diff --git a/src/call/call_video_port.c b/src/call/call_video_port.c index f2e87269..4ffda4ab 100644 --- a/src/call/call_video_port.c +++ b/src/call/call_video_port.c @@ -113,6 +113,7 @@ static void process(void *arg) { if (opening) port.bound = id; pthread_mutex_unlock(&lock); int result = 0, sent = 1; + unsigned sent_count = 0; /* Команды и завершение сессии исполняются одним uasync-потоком: после этой * проверки сессия не может завершиться посреди исполнения снимка. */ struct call_session *session = inst && id ? call_session_find(inst->call, id) : NULL; @@ -142,7 +143,14 @@ static void process(void *arg) { if (id && resume) call_video_resume_receive(inst, id); if (id && key) call_video_request_key(inst, id); if (id && decoded_pending) call_video_decode_result(inst, id, decoded_generation, decoded_accepted); - for (unsigned i = 0; i < tx_count && sent == 1; ++i) sent = call_video_send_frame(inst, &tx[i]); + for (; sent_count < tx_count; ++sent_count) { + sent = call_video_send_frame(inst, &tx[sent_count]); + if (sent != 1) break; + } + if (sent_count < tx_count) + DEBUG_WARN(DEBUG_CATEGORY_CALL, "video port TX frames released call=%llu accepted=%u unsent=%u result=%d " + "first_unsent=%llu last=%llu", (unsigned long long)id, sent_count, tx_count - sent_count, sent, + (unsigned long long)tx[sent_count].frame_id, (unsigned long long)tx[tx_count - 1].frame_id); } for (unsigned i = 0; i < tx_count; ++i) u_free((void *)tx[i].data); pthread_mutex_lock(&lock); @@ -245,6 +253,9 @@ int call_video_port_send(const struct call_video_frame *frames, unsigned count) result = -1; } } + if (result == 0) DEBUG_WARN(DEBUG_CATEGORY_CALL, + "video port TX mailbox busy call=%llu frames=%u first=%llu pending=%u; batch not queued", + (unsigned long long)frames[0].call_id, count, (unsigned long long)frames[0].frame_id, port.tx_count); pthread_mutex_unlock(&lock); return result; } int call_video_port_pull(uint64_t id, struct call_video_frame *out) { diff --git a/tools/chatgui/src/call_video_engine.cpp b/tools/chatgui/src/call_video_engine.cpp index 659f6d06..65be010d 100644 --- a/tools/chatgui/src/call_video_engine.cpp +++ b/tools/chatgui/src/call_video_engine.cpp @@ -36,7 +36,11 @@ struct CallVideoEngine::Impl { int64_t shownPts = -1; uint64_t publicationEpoch = 0; bool publicationPending = false; + unsigned publicationOverwritten = 0; // Только под lock: выбранные кадры, заменённые до GUI callback. + int64_t publicationQueuedAt = 0; int64_t shownAt = 0; + int64_t uiReportAt = 0, uiLastAt = 0, uiWaitMax = 0, uiGapMax = 0; // Только GUI-поток. + unsigned uiPublished = 0, uiOverwritten = 0; int64_t previewReportAt = 0, previewMaxUs = 0; unsigned previewFrames = 0; QString status; @@ -89,22 +93,42 @@ void CallVideoEngine::publishImage(const QImage& image, int64_t pts) { uint64_t epoch; { std::lock_guard guard(m->lock); m->shown = image; m->shownPts = pts; m->shownAt = nowUs(); - if (m->publicationPending) return; - m->publicationPending = true; epoch = m->publicationEpoch; } + if (m->publicationPending) { ++m->publicationOverwritten; return; } + m->publicationPending = true; m->publicationQueuedAt = m->shownAt; epoch = m->publicationEpoch; } QMetaObject::invokeMethod(this, [this, epoch] { - QImage image; int64_t pts, selected; + QImage image; int64_t pts, selected, queued; unsigned overwritten; { std::lock_guard guard(m->lock); if (epoch != m->publicationEpoch) return; - image = m->shown; pts = m->shownPts; selected = m->shownAt; m->publicationPending = false; } + image = m->shown; pts = m->shownPts; selected = m->shownAt; queued = m->publicationQueuedAt; + overwritten = m->publicationOverwritten; m->publicationOverwritten = 0; m->publicationPending = false; } + const int64_t now = nowUs(), wait = now - queued; + ++m->uiPublished; m->uiWaitMax = std::max(m->uiWaitMax, wait); + if (m->uiLastAt) m->uiGapMax = std::max(m->uiGapMax, now - m->uiLastAt); + m->uiLastAt = now; + if (overwritten && !m->uiOverwritten) + DEBUG_WARN(DEBUG_CATEGORY_CALL, "video GUI coalesced call=%llu overwritten=%u notification_wait_us=%lld " + "selected_age_us=%lld pts=%lld mono_us=%lld", (unsigned long long)m->id, overwritten, + (long long)wait, (long long)(now - selected), (long long)pts, (long long)now); + m->uiOverwritten += overwritten; emit imageChanged(image); + if (!m->uiReportAt) m->uiReportAt = now; + if (now - m->uiReportAt >= 1000000) { + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video GUI delivery call=%llu interval_us=%lld published=%u overwritten=%u " + "notification_wait_max_us=%lld delivery_gap_max_us=%lld mono_us=%lld", + (unsigned long long)m->id, (long long)(now - m->uiReportAt), m->uiPublished, m->uiOverwritten, + (long long)m->uiWaitMax, (long long)m->uiGapMax, (long long)now); + m->uiReportAt = now; m->uiPublished = m->uiOverwritten = 0; m->uiWaitMax = m->uiGapMax = 0; + } if (!image.isNull() && pts >= 0 && pts % 1000000 < 34000) - DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video timing stage=publish call=%llu pts=%lld mono_us=%lld ui_wait_us=%lld", - (unsigned long long)m->id, (long long)pts, (long long)nowUs(), (long long)(nowUs() - selected)); + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video timing stage=publish call=%llu pts=%lld mono_us=%lld ui_wait_us=%lld " + "selected_age_us=%lld overwritten=%u", (unsigned long long)m->id, (long long)pts, + (long long)now, (long long)wait, (long long)(now - selected), overwritten); }, Qt::QueuedConnection); } void CallVideoEngine::start(quint64 id) { if (m->running && m->id == id) return; stop(); m->id = id; m->running = true; m_timer.start(); + m->uiReportAt = m->uiLastAt = m->uiWaitMax = m->uiGapMax = 0; m->uiPublished = m->uiOverwritten = 0; try { m->tx = std::thread(&CallVideoEngine::transmit, this); m->rx = std::thread(&CallVideoEngine::receive, this); } catch (const std::exception& error) { DEBUG_ERROR(DEBUG_CATEGORY_CALL, "video worker start: %s", error.what()); stop(); emit statusChanged(error.what()); } } @@ -122,7 +146,7 @@ void CallVideoEngine::stop() { if (m->rx.joinable()) m->rx.join(); if (m->id) call_video_port_close(m->id); { std::lock_guard guard(m->lock); - ++m->publicationEpoch; m->publicationPending = false; m->shown = {}; m->shownPts = -1; } + ++m->publicationEpoch; m->publicationPending = false; m->publicationOverwritten = 0; m->shown = {}; m->shownPts = -1; } m->id = 0; m->enabled = false; emit imageChanged({}); } void CallVideoEngine::setVideo(bool enabled, const QByteArray& cameraId, int width, int height, int codec) { @@ -294,8 +318,11 @@ void CallVideoEngine::receive() { CallVideoDecoder decoder; call_video_playout playout; call_video_playout_init(&playout, m->id); int64_t lastPictureAt = 0; + int64_t reportAt = nowUs(), decodeMax = 0, rxAgeMax = 0, wakeLateMax = 0, requestedWake = 0; + unsigned decoded = 0; uint64_t reportedGeneration = 0, rejectedGeneration = 0; while (m->running) { + if (requestedWake) wakeLateMax = std::max(wakeLateMax, nowUs() - requestedWake); // Один кадр ждёт своего срока, второй позволяет пропустить устаревший показ после паузы CPU. while (pictures.size() < 2 && m->running) { call_video_frame packet{}; @@ -304,12 +331,16 @@ void CallVideoEngine::receive() { QImage image; const int64_t decodeStarted = nowUs(); if (decoder.decode(packet, image)) { + const int64_t decodedAt = nowUs(); + ++decoded; decodeMax = std::max(decodeMax, decodedAt - decodeStarted); + rxAgeMax = std::max(rxAgeMax, decodedAt - packet.received_us); pictures.push_back({{packet.pts_us, packet.received_us}, image}); if (packet.pts_us % 1000000 < 34000) DEBUG_DEBUG(DEBUG_CATEGORY_CALL, - "video timing stage=decode call=%llu frame=%llu pts=%lld mono_us=%lld decode_us=%lld queue=%zu", + "video timing stage=decode call=%llu frame=%llu pts=%lld mono_us=%lld decode_us=%lld rx_age_us=%lld queue=%zu", (unsigned long long)m->id, (unsigned long long)packet.frame_id, (long long)packet.pts_us, - (long long)nowUs(), (long long)(nowUs() - decodeStarted), pictures.size()); + (long long)decodedAt, (long long)(decodedAt - decodeStarted), + (long long)(decodedAt - packet.received_us), pictures.size()); if (reportedGeneration != packet.format.generation) { reportedGeneration = packet.format.generation; call_video_port_decoded(m->id, reportedGeneration, 1); } @@ -321,6 +352,15 @@ void CallVideoEngine::receive() { } int64_t now = nowUs(); call_clock_snapshot clock{}; call_audio_get_clock(m->id, now, &clock); + if (now - reportAt >= 1000000) { + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video RX worker call=%llu interval_us=%lld decoded=%u decode_max_us=%lld " + "rx_to_decode_max_us=%lld wake_late_max_us=%lld ready=%zu audio_valid=%d audio_measured=%d " + "audio_pts=%lld played=%llu written=%llu mono_us=%lld", + (unsigned long long)m->id, (long long)(now - reportAt), decoded, (long long)decodeMax, (long long)rxAgeMax, + (long long)wakeLateMax, pictures.size(), clock.valid, clock.measured, (long long)clock.pts_us, + (unsigned long long)clock.played_samples, (unsigned long long)clock.written_samples, (long long)now); + reportAt = now; decoded = 0; decodeMax = rxAgeMax = wakeLateMax = 0; + } auto action = call_video_playout_poll(&playout, pictures.empty() ? nullptr : &pictures.front().timing, pictures.size() > 1 ? &pictures[1].timing : nullptr, now, clock.valid, clock.pts_us); if (action != CALL_VIDEO_PLAYOUT_WAIT) { @@ -331,6 +371,7 @@ void CallVideoEngine::receive() { (unsigned long long)m->id, (long long)f.timing.pts_us, (long long)now, (long long)clock.pts_us); } pictures.pop_front(); + requestedWake = 0; continue; } // VIDEO_OFF пока отсутствует в протоколе: убираем застывшую картинку после прекращения показа. @@ -338,6 +379,9 @@ void CallVideoEngine::receive() { publishImage({}, -1); lastPictureAt = 0; DEBUG_INFO(DEBUG_CATEGORY_CALL, "video playback hidden: no playable frame for 5s"); } - std::this_thread::sleep_for(std::chrono::microseconds(std::max(100, std::min(5000, playout.deadline_us - nowUs())))); + const int64_t sleepAt = nowUs(); + const int64_t waitUs = std::max(100, std::min(5000, playout.deadline_us - sleepAt)); + requestedWake = sleepAt + waitUs; + std::this_thread::sleep_for(std::chrono::microseconds(waitUs)); } } diff --git a/tools/chatgui/transport/audio_diagnostics.cpp b/tools/chatgui/transport/audio_diagnostics.cpp index b8fd1bd7..b7aa645d 100644 --- a/tools/chatgui/transport/audio_diagnostics.cpp +++ b/tools/chatgui/transport/audio_diagnostics.cpp @@ -1,20 +1,28 @@ #include "audio_diagnostics.h" -#ifdef __linux__ +#if defined(__linux__) || defined(_WIN32) #include #include #include #include #include -#include #include #include #include #include #include +#ifdef _WIN32 +#ifndef NOMINMAX +#define NOMINMAX +#endif +#include +#include +#else +#include #include #include #include +#endif extern "C" { #include "../../../lib/debug_config.h" @@ -36,6 +44,7 @@ struct Event { char text[192]; audio_capture_timing capture{}; audio_playback_timing playback{}; + audio_wasapi_timing wasapi{}; }; struct Slot { std::atomic sequence{0}; Event event{}; }; std::array queue; @@ -44,17 +53,30 @@ std::atomic running{false}; uint64_t readPosition = 0; std::thread reporter; -uint64_t now(clockid_t clock) { +uint64_t wallNow() { + return std::chrono::duration_cast(std::chrono::steady_clock::now().time_since_epoch()).count(); +} + +uint64_t cpuNow() { +#ifdef _WIN32 + FILETIME created, exited, kernel, user; + if (!GetThreadTimes(GetCurrentThread(), &created, &exited, &kernel, &user)) return 0; + uint64_t kernelTicks = (uint64_t(kernel.dwHighDateTime) << 32) | kernel.dwLowDateTime; + uint64_t userTicks = (uint64_t(user.dwHighDateTime) << 32) | user.dwLowDateTime; + return (kernelTicks + userTicks) * 100; +#else timespec ts{}; - clock_gettime(clock, &ts); + clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts); return uint64_t(ts.tv_sec) * kSecond + uint64_t(ts.tv_nsec); +#endif } /* Ограниченная MPSC-очередь: producer не ждёт, не выделяет память и не пишет лог. */ void publish(const void* device, int kind, int stage, int64_t value, int64_t detail, const char* text, - const audio_capture_timing* capture = nullptr, const audio_playback_timing* playback = nullptr) { + const audio_capture_timing* capture = nullptr, const audio_playback_timing* playback = nullptr, + const audio_wasapi_timing* wasapi = nullptr) { if (!running.load(std::memory_order_relaxed)) return; - const auto wall = now(CLOCK_MONOTONIC), cpu = now(CLOCK_THREAD_CPUTIME_ID); + const auto wall = wallNow(), cpu = cpuNow(); uint64_t pos = writePosition.load(std::memory_order_relaxed); for (int attempt = 0; attempt < 4; ++attempt) { auto& slot = queue[pos % kCapacity]; @@ -64,9 +86,14 @@ void publish(const void* device, int kind, int stage, int64_t value, int64_t det auto& e = slot.event; e.device = reinterpret_cast(device); e.wall = wall; e.cpu = cpu; e.kind = kind; e.stage = stage; e.value = value; e.detail = detail; +#ifdef _WIN32 + e.tid = GetCurrentThreadId(); +#else e.tid = syscall(SYS_gettid); +#endif if (capture) e.capture = *capture; if (playback) e.playback = *playback; + if (wasapi) e.wasapi = *wasapi; e.text[0] = 0; if (text) { std::strncpy(e.text, text, sizeof(e.text) - 1); @@ -116,6 +143,10 @@ struct Device { TimingRange captureLatency, captureBlock, playbackLatency, playbackBlock; uint64_t playbackBlocks = 0, playbackFrames = 0; int64_t playbackMaxConverter = 0; + audio_wasapi_timing wasapi{}; + bool wasapiSeen = false; + uint64_t wasapiBlocks = 0, wasapiFailures = 0, wasapiSampleUs = 0; + TimingRange wasapiPadding, wasapiLatency, wasapiConverter; }; void consume(const Event& e, std::map& devices) { @@ -137,7 +168,29 @@ void consume(const Event& e, std::map& devices) { return; } auto& d = devices[e.device]; - if (e.kind == AUDIO_DIAG_CAPTURE_CLOCK) { + if (e.kind == AUDIO_DIAG_WASAPI_PLAYBACK) { + const auto& w = e.wasapi; + if (!d.wasapiSeen || w.rate != d.wasapi.rate || w.device_rate != d.wasapi.device_rate + || w.buffer_frames != d.wasapi.buffer_frames || w.shared != d.wasapi.shared + || w.period_frames != d.wasapi.period_frames || w.periods != d.wasapi.periods + || w.fixed_callback != d.wasapi.fixed_callback) { + DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: WASAPI playback dev=%p role=%s client_rate=%u device_rate=%u " + "buffer_frames=%u period_frames=%u periods=%u shared=%d fixed_callback=%d " + "snapshot=before-client-callback clock=callback-estimate unchanged=1 stream_latency_is_not_padding=1", + (void*)e.device, d.label.c_str(), w.rate, w.device_rate, w.buffer_frames, w.period_frames, w.periods, + w.shared, w.fixed_callback); + } + bool failed = w.padding_result < 0 || w.latency_result < 0 || !w.device_rate || !w.rate; + if (failed && ++d.wasapiFailures == 1) + DEBUG_WARN(DEBUG_CATEGORY_CALL, "AudioDiag: WASAPI snapshot failed dev=%p role=%s padding_hresult=0x%08x " + "latency_hresult=0x%08x client_rate=%u device_rate=%u mono_us=%llu", (void*)e.device, d.label.c_str(), + (unsigned)w.padding_result, (unsigned)w.latency_result, w.rate, w.device_rate, (unsigned long long)(e.wall / 1000)); + if (w.padding_result >= 0 && w.device_rate && w.shared) + d.wasapiPadding.add(int64_t(w.padding_frames) * 1000000 / w.device_rate); + if (w.latency_result >= 0) d.wasapiLatency.add(w.stream_latency_us); + d.wasapiConverter.add(w.converter_us); + d.wasapi = w; d.wasapiSeen = true; ++d.wasapiBlocks; d.wasapiSampleUs = e.wall / 1000; + } else if (e.kind == AUDIO_DIAG_CAPTURE_CLOCK) { const auto& c = e.capture; const int64_t expected = d.capture.rate ? d.capture.first_us + int64_t(d.capture.frames) * 1000000 / d.capture.rate : c.first_us; const int64_t delta = c.first_us - expected; @@ -191,7 +244,7 @@ void consume(const Event& e, std::map& devices) { auto& s = d.stages[e.stage]; if (s.entered && s.tid == e.tid && e.wall >= s.entered) { s.maxWork = std::max(s.maxWork, e.wall - s.entered); - s.maxCpu = std::max(s.maxCpu, e.cpu - s.cpu); + if (s.cpu && e.cpu >= s.cpu) s.maxCpu = std::max(s.maxCpu, e.cpu - s.cpu); } s.output = e.detail; s.entered = 0; @@ -213,6 +266,18 @@ void report(std::map& devices, uint64_t wall, double elapsed) (unsigned long long)dropped); std::set stalledThreads; for (auto& [key, d] : devices) { + if (d.wasapiBlocks) { + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "AudioDiag: WASAPI queue dev=%p role=%s id=%016llx samples=%llu failed=%llu " + "padding_samples=%llu padding_us=%lld/%lld/%lld stream_latency_us=%lld/%lld/%lld converter_us=%lld/%lld/%lld " + "last_padding_frames=%u mapped_frames=%u callback_frames=%u sample_mono_us=%llu interval_s=%.3f", + (void*)key, d.label.c_str(), (unsigned long long)d.id, (unsigned long long)d.wasapiBlocks, + (unsigned long long)d.wasapiFailures, (unsigned long long)d.wasapiPadding.count, + (long long)d.wasapiPadding.low, (long long)d.wasapiPadding.average(), (long long)d.wasapiPadding.high, + (long long)d.wasapiLatency.low, (long long)d.wasapiLatency.average(), (long long)d.wasapiLatency.high, + (long long)d.wasapiConverter.low, (long long)d.wasapiConverter.average(), (long long)d.wasapiConverter.high, + d.wasapi.padding_frames, d.wasapi.mapped_frames, d.wasapi.frames, (unsigned long long)d.wasapiSampleUs, elapsed); + d.wasapiBlocks = d.wasapiFailures = 0; d.wasapiPadding = {}; d.wasapiLatency = {}; d.wasapiConverter = {}; + } 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/%lld converter_max_us=%lld block_us=%lld/%lld/%lld", @@ -243,7 +308,8 @@ void report(std::map& devices, uint64_t wall, double elapsed) const double pending = s.entered && wall >= s.entered ? (wall - s.entered) / 1e6 : 0; const double idle = wall >= s.last ? (wall - s.last) / 1e6 : 0; const bool delayed = s.maxWork > 50000000 || s.maxGap > 50000000 || pending > 50 || idle > 100; - const auto level = delayed ? DEBUG_LEVEL_WARN : DEBUG_LEVEL_TRACE; + const auto level = delayed ? DEBUG_LEVEL_WARN + : d.wasapiSeen && (i == AUDIO_DIAG_WRITE || i == AUDIO_DIAG_CALLBACK) ? DEBUG_LEVEL_DEBUG : DEBUG_LEVEL_TRACE; if (s.delayed && !delayed) DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: audio timing recovered dev=%p role=%s id=%016llx stage=%s tid=%ld", (void*)key, d.label.c_str(), (unsigned long long)d.id, kStages[i], s.tid); @@ -273,6 +339,7 @@ void report(std::map& devices, uint64_t wall, double elapsed) (unsigned long long)d.faults[AUDIO_DIAG_BACKEND_OVERFLOW], (unsigned long long)d.faults[AUDIO_DIAG_ERROR]); d.faults.fill(0); } +#ifdef __linux__ for (auto tid : stalledThreads) { const auto path = std::string("/proc/self/task/") + std::to_string(tid) + "/"; std::ifstream waitFile(path + "wchan"), schedFile(path + "schedstat"); @@ -283,20 +350,21 @@ void report(std::map& devices, uint64_t wall, double elapsed) tid, wait.c_str(), cpu / 1e6, ready / 1e6, (unsigned long long)slices); else DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "AudioDiag: thread tid=%ld proc snapshot unavailable (thread may have exited)", tid); } +#endif } void run() { std::map devices; - auto lastReport = now(CLOCK_MONOTONIC); + auto lastReport = wallNow(); for (;;) { Event e; for (uint64_t n = 0; n < kCapacity && take(e); ++n) consume(e, devices); - const auto wall = now(CLOCK_MONOTONIC); + const auto wall = wallNow(); if (wall - lastReport >= kSecond) { report(devices, wall, (wall - lastReport) / double(kSecond)); lastReport = wall; } if (!running.load(std::memory_order_acquire)) break; std::this_thread::sleep_for(std::chrono::milliseconds(20)); } - report(devices, now(CLOCK_MONOTONIC), 1.0); + report(devices, wallNow(), 1.0); } } // namespace @@ -311,7 +379,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; ranges=min/avg/max timestamps=CLOCK_MONOTONIC", + DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: started capacity=%llu check_interval=1s category=call normal=trace clocks=debug faults=warn; ranges=min/avg/max timestamps=monotonic", (unsigned long long)kCapacity); } void audio_diag_stop(void) { @@ -334,6 +402,9 @@ void audio_diag_capture_clock(const void* device, const audio_capture_timing* ti void audio_diag_playback_clock(const void* device, const audio_playback_timing* timing) { publish(device, AUDIO_DIAG_PLAYBACK_CLOCK, AUDIO_DIAG_WRITE, 0, 0, nullptr, nullptr, timing); } +void audio_diag_wasapi_playback(const void* device, const audio_wasapi_timing* timing) { + publish(device, AUDIO_DIAG_WASAPI_PLAYBACK, AUDIO_DIAG_WRITE, 0, 0, nullptr, nullptr, nullptr, timing); +} #else void audio_diag_start(void) {} void audio_diag_stop(void) {} @@ -342,4 +413,5 @@ void audio_diag_label(const void*, uint64_t, const char*) {} void audio_diag_log(const void*, unsigned int, const char*) {} void audio_diag_capture_clock(const void*, const audio_capture_timing*) {} void audio_diag_playback_clock(const void*, const audio_playback_timing*) {} +void audio_diag_wasapi_playback(const void*, const audio_wasapi_timing*) {} #endif diff --git a/tools/chatgui/transport/audio_diagnostics.h b/tools/chatgui/transport/audio_diagnostics.h index 2beeffbd..102035c3 100644 --- a/tools/chatgui/transport/audio_diagnostics.h +++ b/tools/chatgui/transport/audio_diagnostics.h @@ -2,6 +2,8 @@ #include +/* Desktop-аудиодиагностика: callbacks передают числовые снимки в ограниченную очередь. + * Отдельный reporter пишет сводки в категорию call; start/stop принадлежат владельцу устройств. */ #ifdef __cplusplus extern "C" { #endif @@ -16,7 +18,7 @@ enum audio_diag_kind { AUDIO_DIAG_ENTER, AUDIO_DIAG_LEAVE, AUDIO_DIAG_OPEN, AUDIO_DIAG_CLOSE, AUDIO_DIAG_NOTIFY, AUDIO_DIAG_BACKEND_STARTED, AUDIO_DIAG_HOLE, AUDIO_DIAG_UNFILLED, AUDIO_DIAG_CAPTURE_DROP, AUDIO_DIAG_NO_PROGRESS, AUDIO_DIAG_BACKEND_UNDERRUN, AUDIO_DIAG_BACKEND_OVERFLOW, AUDIO_DIAG_ERROR, AUDIO_DIAG_LABEL, AUDIO_DIAG_LOG, - AUDIO_DIAG_CAPTURE_CLOCK, AUDIO_DIAG_PLAYBACK_CLOCK + AUDIO_DIAG_CAPTURE_CLOCK, AUDIO_DIAG_PLAYBACK_CLOCK, AUDIO_DIAG_WASAPI_PLAYBACK }; struct audio_capture_timing { @@ -31,6 +33,17 @@ struct audio_playback_timing { int measured; }; +/* Снимок перед заполнением client PCM. Padding — текущая очередь, stream_latency — отдельное + * свойство WASAPI; их сумма не объявляется измеренным временем физического воспроизведения. */ +struct audio_wasapi_timing { + int64_t stream_latency_us, converter_us; // Задержка stream API и converter/cache соответственно. + unsigned frames, rate, device_rate; // Размер client callback, client/device частоты в Гц. + unsigned padding_frames, buffer_frames, period_frames, periods; // Размеры очереди/буфера в device PCM. + unsigned mapped_frames; // Уже заполненная часть незавершённого WASAPI buffer. + int shared, fixed_callback; // Режим доступа и наличие дополнительного callback-буфера. + int32_t padding_result, latency_result; // HRESULT каждого запроса; отрицательное значение — ошибка. +}; + /* start/stop — управляющий поток; перед stop все producers должны быть остановлены. */ void audio_diag_start(void); void audio_diag_stop(void); @@ -39,6 +52,8 @@ void audio_diag_label(const void* device, uint64_t id, const char* name); void audio_diag_log(const void* log, unsigned int level, const char* message); void audio_diag_capture_clock(const void* device, const struct audio_capture_timing* timing); void audio_diag_playback_clock(const void* device, const struct audio_playback_timing* timing); +/* Вызывать из playback callback; снимок копируется, устройством reporter не пользуется. */ +void audio_diag_wasapi_playback(const void* device, const struct audio_wasapi_timing* timing); #ifdef __cplusplus } diff --git a/tools/chatgui/transport/miniaudio_impl.c b/tools/chatgui/transport/miniaudio_impl.c index 43bc4a34..65ac12c6 100644 --- a/tools/chatgui/transport/miniaudio_impl.c +++ b/tools/chatgui/transport/miniaudio_impl.c @@ -9,9 +9,11 @@ static void audio_capture_hole(uint64_t offset); #define MA_AUDIO_TIMING_BEGIN(device, frames, capture) audio_timing_begin(device, frames, capture) #define MA_AUDIO_TIMING_END() audio_timing_end() #define MA_AUDIO_CAPTURE_HOLE(offset) audio_capture_hole(offset) +#define MA_DIAGNOSTIC_DEVICE_INIT(device) audio_diag_pulse_init(device) +#endif +#if defined(__linux__) || defined(_WIN32) #define MA_DIAGNOSTIC_EVENT(device, kind, stage, value, detail) audio_diag_event(device, kind, stage, value, detail) #define MA_DIAGNOSTIC_LOG(log, level, message) audio_diag_log(log, level, message) -#define MA_DIAGNOSTIC_DEVICE_INIT(device) audio_diag_pulse_init(device) #endif #define MINIAUDIO_IMPLEMENTATION #include "../../../lib/miniaudio.h" @@ -211,6 +213,29 @@ static void audio_timing_end(void) { audio_timing.device = NULL; } static void audio_capture_hole(uint64_t offset) { audio_timing.hole_pending = 1; audio_timing.hole_offset = offset; } #endif +#ifdef MA_SUPPORT_WASAPI +/* Только поток устройства: API-снимок не меняет PTS и не подменяет callback-estimate. + * WASAPI заполняется после callback; время блокирующего write видно в стадии write. */ +static void audio_wasapi_playback_snapshot(ma_device* device, unsigned int frames) { + if (device->pContext->backend != ma_backend_wasapi || device->type != ma_device_type_playback) return; + ma_IAudioClient* client = (ma_IAudioClient*)device->wasapi.pAudioClientPlayback; + if (!client) { audio_diag_event(device, AUDIO_DIAG_ERROR, AUDIO_DIAG_WRITE, 1, MA_INVALID_OPERATION); return; } + struct audio_wasapi_timing timing = {0}; + MA_REFERENCE_TIME latency = 0; + timing.frames = frames; timing.rate = device->sampleRate; timing.device_rate = device->playback.internalSampleRate; + timing.buffer_frames = device->wasapi.actualBufferSizeInFramesPlayback; + timing.period_frames = device->playback.internalPeriodSizeInFrames; timing.periods = device->playback.internalPeriods; + timing.mapped_frames = device->wasapi.mappedBufferPlaybackLen; + timing.shared = device->playback.shareMode == ma_share_mode_shared; timing.fixed_callback = !device->noFixedSizedCallback; + timing.padding_result = ma_IAudioClient_GetCurrentPadding(client, &timing.padding_frames); + timing.latency_result = ma_IAudioClient_GetStreamLatency(client, &latency); + if (timing.latency_result >= 0) timing.stream_latency_us = latency / 10; + if (timing.rate) timing.converter_us = (int64_t)(ma_data_converter_get_input_latency(&device->playback.converter) + + device->playback.inputCacheRemaining) * 1000000 / timing.rate; + audio_diag_wasapi_playback(device, &timing); +} +#endif + int64_t audio_stream_frame_time(ma_device* device, unsigned int frames, int* valid) { *valid = 0; #ifdef __linux__ @@ -219,6 +244,8 @@ int64_t audio_stream_frame_time(ma_device* device, unsigned int frames, int* val audio_timing.frames += frames; *valid = audio_timing.valid; return time; } +#elif defined(MA_SUPPORT_WASAPI) + audio_wasapi_playback_snapshot(device, frames); #else (void)device; (void)frames; #endif