From b16a4995b7ec6756831a8ef7050d6b1e23c649e5 Mon Sep 17 00:00:00 2001 From: evgeny Date: Wed, 7 Oct 2026 21:09:46 +0200 Subject: [PATCH] logging: quiet routine audio and route polling, report audio recovery --- src/dm/dm_core.c | 2 +- tools/chatgui/transport/audio_diagnostics.cpp | 20 +++++++++++++------ 2 files changed, 15 insertions(+), 7 deletions(-) diff --git a/src/dm/dm_core.c b/src/dm/dm_core.c index 88f4ae02..863b2255 100644 --- a/src/dm/dm_core.c +++ b/src/dm/dm_core.c @@ -1179,7 +1179,7 @@ int dm_call_route(struct UTUN_INSTANCE* inst, const char* conv_id, uint64_t* pee } sqlite3_finalize(st); int available = *peer && *peer != inst->node_id && dm_find_route_group(inst, *peer, preferred, group_id, 1); - DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "PM route: conv=%s peer=%llu preferred=%llu group=%llu available=%d", + DEBUG_TRACE(DEBUG_CATEGORY_CALL, "PM route: conv=%s peer=%llu preferred=%llu group=%llu available=%d", conv_id, (unsigned long long)*peer, (unsigned long long)preferred, (unsigned long long)*group_id, available); return available; } diff --git a/tools/chatgui/transport/audio_diagnostics.cpp b/tools/chatgui/transport/audio_diagnostics.cpp index 5ff64257..d7f9105d 100644 --- a/tools/chatgui/transport/audio_diagnostics.cpp +++ b/tools/chatgui/transport/audio_diagnostics.cpp @@ -88,6 +88,7 @@ struct Stage { uint64_t entered = 0, cpu = 0, last = 0, calls = 0, frames = 0, maxGap = 0, maxWork = 0, maxCpu = 0; int64_t input = 0, output = 0; long tid = 0; + bool delayed = false; }; struct Device { std::string label = "unlabelled"; @@ -165,13 +166,18 @@ void report(std::map& devices, uint64_t wall, double elapsed) if (!s.last) continue; 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 auto level = s.maxWork > 50000000 || s.maxGap > 50000000 || pending > 50 || idle > 100 - ? DEBUG_LEVEL_WARN : DEBUG_LEVEL_DEBUG; + const bool delayed = s.maxWork > 50000000 || s.maxGap > 50000000 || pending > 50 || idle > 100; + const auto level = delayed ? DEBUG_LEVEL_WARN : 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); + s.delayed = delayed; if (level == DEBUG_LEVEL_WARN) stalledThreads.insert(s.tid); // Без вызова backend-API: reporter никогда не трогает живые ma_device/pa_stream. if (debug_should_output(level, DEBUG_CATEGORY_CALL)) debug_output(level, DEBUG_CATEGORY_CALL, __func__, __FILE__, __LINE__, - "AudioDiag: dev=%p role=%s id=%016llx stage=%s tid=%ld interval=%.3fs calls=%.1f/s frames=%.0f/s " + "AudioDiag: %s dev=%p role=%s id=%016llx stage=%s tid=%ld interval=%.3fs calls=%.1f/s frames=%.0f/s " "gap_max=%.2fms work_max=%.2fms cpu_max=%.2fms pending=%.2fms since_enter=%.2fms in_detail=%lld out_detail=%lld mono_ms=%llu", + delayed ? "audio delayed (limits: work/gap/pending=50ms idle=100ms)" : "audio timing", (void*)key, d.label.c_str(), (unsigned long long)d.id, kStages[i], s.tid, elapsed, s.calls / elapsed, s.frames / elapsed, s.maxGap / 1e6, s.maxWork / 1e6, s.maxCpu / 1e6, pending, idle, (long long)s.input, (long long)s.output, (unsigned long long)(wall / 1000000)); @@ -180,8 +186,10 @@ void report(std::map& devices, uint64_t wall, double elapsed) if (d.faults[AUDIO_DIAG_HOLE] || d.faults[AUDIO_DIAG_UNFILLED] || d.faults[AUDIO_DIAG_CAPTURE_DROP] || d.faults[AUDIO_DIAG_NO_PROGRESS] || d.faults[AUDIO_DIAG_BACKEND_UNDERRUN] || d.faults[AUDIO_DIAG_BACKEND_OVERFLOW] || d.faults[AUDIO_DIAG_ERROR]) - DEBUG_WARN(DEBUG_CATEGORY_CALL, "AudioDiag: dev=%p hole_frames=%llu unfilled_frames=%llu capture_drop_frames=%llu " - "no_progress=%llu backend_underruns=%llu backend_overflows=%llu errors=%llu", (void*)key, + DEBUG_WARN(DEBUG_CATEGORY_CALL, "AudioDiag: audio faults dev=%p role=%s id=%016llx interval=%.3fs " + "hole_frames=%llu unfilled_frames=%llu capture_drop_frames=%llu " + "no_progress=%llu backend_underruns=%llu backend_overflows=%llu errors=%llu", + (void*)key, d.label.c_str(), (unsigned long long)d.id, elapsed, (unsigned long long)d.faults[AUDIO_DIAG_HOLE], (unsigned long long)d.faults[AUDIO_DIAG_UNFILLED], (unsigned long long)d.faults[AUDIO_DIAG_CAPTURE_DROP], (unsigned long long)d.faults[AUDIO_DIAG_NO_PROGRESS], @@ -227,7 +235,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 reporting=1s category=call; timestamps=CLOCK_MONOTONIC", + DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: started capacity=%llu check_interval=1s category=call normal=trace faults=warn; timestamps=CLOCK_MONOTONIC", (unsigned long long)kCapacity); } void audio_diag_stop(void) {