From 1da19276e5497bf27d80112e9c71ce43354e0b92 Mon Sep 17 00:00:00 2001 From: evgeny Date: Thu, 15 Oct 2026 03:12:16 +0200 Subject: [PATCH] Trace raw capture timing and PulseAudio latency without callback logging --- tools/chatgui/transport/audio_diagnostics.cpp | 48 ++++++++++++++++++- tools/chatgui/transport/audio_diagnostics.h | 10 +++- tools/chatgui/transport/miniaudio_impl.c | 5 ++ 3 files changed, 60 insertions(+), 3 deletions(-) diff --git a/tools/chatgui/transport/audio_diagnostics.cpp b/tools/chatgui/transport/audio_diagnostics.cpp index d7f9105d..5ed450db 100644 --- a/tools/chatgui/transport/audio_diagnostics.cpp +++ b/tools/chatgui/transport/audio_diagnostics.cpp @@ -34,6 +34,7 @@ struct Event { int kind, stage; long tid; char text[192]; + audio_capture_timing capture{}; }; struct Slot { std::atomic sequence{0}; Event event{}; }; std::array queue; @@ -49,7 +50,8 @@ uint64_t now(clockid_t clock) { } /* Ограниченная MPSC-очередь: producer не ждёт, не выделяет память и не пишет лог. */ -void publish(const void* device, int kind, int stage, int64_t value, int64_t detail, const char* text) { +void publish(const void* device, int kind, int stage, int64_t value, int64_t detail, const char* text, + const audio_capture_timing* capture = nullptr) { if (!running.load(std::memory_order_relaxed)) return; const auto wall = now(CLOCK_MONOTONIC), cpu = now(CLOCK_THREAD_CPUTIME_ID); uint64_t pos = writePosition.load(std::memory_order_relaxed); @@ -61,6 +63,7 @@ void publish(const void* device, int kind, int stage, int64_t value, int64_t det e.device = reinterpret_cast(device); e.wall = wall; e.cpu = cpu; e.kind = kind; e.stage = stage; e.value = value; e.detail = detail; e.tid = syscall(SYS_gettid); + if (capture) e.capture = *capture; e.text[0] = 0; if (text) { std::strncpy(e.text, text, sizeof(e.text) - 1); @@ -95,6 +98,9 @@ struct Device { uint64_t id = 0; std::array stages{}; 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; }; void consume(const Event& e, std::map& devices) { @@ -116,7 +122,31 @@ void consume(const Event& e, std::map& devices) { return; } auto& d = devices[e.device]; - if (e.kind == AUDIO_DIAG_LABEL) { + 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; + 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 (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 " + "expected_us=%lld first_us=%lld delta_us=%lld latency_us=%lld->%lld converter_us=%lld->%lld " + "measured=%d->%d missing=%d mono_us=%llu", (void*)e.device, d.label.c_str(), + (unsigned long long)d.captureSequence, c.frames, c.rate, (long long)expected, (long long)c.first_us, + (long long)delta, (long long)d.capture.latency_us, (long long)c.latency_us, + (long long)d.capture.converter_us, (long long)c.converter_us, d.capture.measured, c.measured, + c.missing, (unsigned long long)(e.wall / 1000)); + } + ++d.captureBlocks; d.captureFrames += c.frames; d.captureSequence += c.frames; + if (c.missing) d.captureMissing += c.frames; + if (!c.measured) ++d.captureEstimated; + d.capture = c; + } 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); } else if (e.kind == AUDIO_DIAG_OPEN) { @@ -161,6 +191,16 @@ void report(std::map& devices, uint64_t wall, double elapsed) (unsigned long long)dropped); std::set stalledThreads; for (auto& [key, d] : devices) { + 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", + (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); + d.captureBlocks = d.captureFrames = d.captureJumps = d.captureMissing = d.captureEstimated = 0; + } for (int i = 0; i < AUDIO_DIAG_STAGE_COUNT; ++i) { auto& s = d.stages[i]; if (!s.last) continue; @@ -252,10 +292,14 @@ 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) { publish(log, AUDIO_DIAG_LOG, -1, level, 0, message); } +void audio_diag_capture_clock(const void* device, const audio_capture_timing* timing) { + publish(device, AUDIO_DIAG_CAPTURE_CLOCK, AUDIO_DIAG_READ, 0, 0, nullptr, timing); +} #else void audio_diag_start(void) {} void audio_diag_stop(void) {} void audio_diag_event(const void*, int, int, int64_t, int64_t) {} 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*) {} #endif diff --git a/tools/chatgui/transport/audio_diagnostics.h b/tools/chatgui/transport/audio_diagnostics.h index 8bc3ddb8..25d46665 100644 --- a/tools/chatgui/transport/audio_diagnostics.h +++ b/tools/chatgui/transport/audio_diagnostics.h @@ -15,7 +15,14 @@ enum audio_diag_stage { 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_NO_PROGRESS, AUDIO_DIAG_BACKEND_UNDERRUN, AUDIO_DIAG_BACKEND_OVERFLOW, AUDIO_DIAG_ERROR, AUDIO_DIAG_LABEL, AUDIO_DIAG_LOG, + AUDIO_DIAG_CAPTURE_CLOCK +}; + +struct audio_capture_timing { + int64_t first_us, latency_us, converter_us; + unsigned frames, rate; + int measured, missing; }; /* start/stop — управляющий поток; перед stop все producers должны быть остановлены. */ @@ -24,6 +31,7 @@ void audio_diag_stop(void); void audio_diag_event(const void* device, int kind, int stage, int64_t value, int64_t detail); 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); #ifdef __cplusplus } diff --git a/tools/chatgui/transport/miniaudio_impl.c b/tools/chatgui/transport/miniaudio_impl.c index 6450e834..59bed351 100644 --- a/tools/chatgui/transport/miniaudio_impl.c +++ b/tools/chatgui/transport/miniaudio_impl.c @@ -161,6 +161,11 @@ static void audio_timing_begin(void* opaque, unsigned int frames, int capture) { time += latency + (int64_t)(converter_delay + device->playback.inputCacheRemaining) * 1000000 / device->sampleRate; } audio_timing.first_us = time; audio_timing.frames = 0; + if (capture) { + struct audio_capture_timing timing = {time, latency, (int64_t)converter_delay * 1000000 / device->sampleRate, + frames, rate, audio_timing.valid, audio_timing.missing}; + audio_diag_capture_clock(device, &timing); + } audio_timing.hole_pending = 0; } static void audio_timing_end(void) { audio_timing.device = NULL; }