Trace raw capture timing and PulseAudio latency without callback logging

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<uint64_t> sequence{0}; Event event{}; };
 std::array<Slot, kCapacity> 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<uintptr_t>(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<Stage, AUDIO_DIAG_STAGE_COUNT> stages{};
     std::array<uint64_t, AUDIO_DIAG_LOG + 1> 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<uintptr_t, Device>& devices) {
@@ -116,7 +122,31 @@ void consume(const Event& e, std::map<uintptr_t, Device>& 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<uintptr_t, Device>& devices, uint64_t wall, double elapsed)
                             (unsigned long long)dropped);
     std::set<long> 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

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
 }

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; }