Browse Source

logging: quiet routine audio and route polling, report audio recovery

master
evgeny 5 days ago
parent
commit
b16a4995b7
  1. 2
      src/dm/dm_core.c
  2. 20
      tools/chatgui/transport/audio_diagnostics.cpp

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

20
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<uintptr_t, Device>& 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<uintptr_t, Device>& 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) {

Loading…
Cancel
Save