You can not select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
333 lines
19 KiB
333 lines
19 KiB
#include "audio_diagnostics.h" |
|
|
|
#ifdef __linux__ |
|
#include <algorithm> |
|
#include <array> |
|
#include <atomic> |
|
#include <chrono> |
|
#include <cstring> |
|
#include <fstream> |
|
#include <set> |
|
#include <map> |
|
#include <string> |
|
#include <system_error> |
|
#include <thread> |
|
#include <time.h> |
|
#include <sys/syscall.h> |
|
#include <unistd.h> |
|
|
|
extern "C" { |
|
#include "../../../lib/debug_config.h" |
|
} |
|
|
|
namespace { |
|
constexpr uint64_t kCapacity = 8192; |
|
constexpr uint64_t kSecond = 1000000000; |
|
const char* const kFaults[] = {"hole", "unfilled", "capture-drop", "no-progress", "backend-underrun", "backend-overflow", "error"}; |
|
const char* const kStages[] = {"loop", "read", "write", "map", "submit", "duplex", "callback", "feed", "pull"}; |
|
static_assert(std::atomic<uint64_t>::is_always_lock_free); |
|
|
|
struct Event { |
|
uintptr_t device; |
|
uint64_t wall, cpu; |
|
int64_t value, detail; |
|
int kind, stage; |
|
long tid; |
|
char text[192]; |
|
audio_capture_timing capture{}; |
|
audio_playback_timing playback{}; |
|
}; |
|
struct Slot { std::atomic<uint64_t> sequence{0}; Event event{}; }; |
|
std::array<Slot, kCapacity> queue; |
|
std::atomic<uint64_t> writePosition{0}, lost{0}; |
|
std::atomic<bool> running{false}; |
|
uint64_t readPosition = 0; |
|
std::thread reporter; |
|
|
|
uint64_t now(clockid_t clock) { |
|
timespec ts{}; |
|
clock_gettime(clock, &ts); |
|
return uint64_t(ts.tv_sec) * kSecond + uint64_t(ts.tv_nsec); |
|
} |
|
|
|
/* Ограниченная 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) { |
|
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); |
|
for (int attempt = 0; attempt < 4; ++attempt) { |
|
auto& slot = queue[pos % kCapacity]; |
|
const auto seq = slot.sequence.load(std::memory_order_acquire); |
|
if (seq == pos && writePosition.compare_exchange_weak(pos, pos + 1, std::memory_order_relaxed)) { |
|
auto& e = slot.event; |
|
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; |
|
if (playback) e.playback = *playback; |
|
e.text[0] = 0; |
|
if (text) { |
|
std::strncpy(e.text, text, sizeof(e.text) - 1); |
|
e.text[sizeof(e.text) - 1] = 0; |
|
} |
|
slot.sequence.store(pos + 1, std::memory_order_release); |
|
return; |
|
} |
|
if (seq < pos) break; // Полное кольцо. |
|
pos = writePosition.load(std::memory_order_relaxed); |
|
} |
|
lost.fetch_add(1, std::memory_order_relaxed); |
|
} |
|
|
|
bool take(Event& event) { |
|
auto& slot = queue[readPosition % kCapacity]; |
|
if (slot.sequence.load(std::memory_order_acquire) != readPosition + 1) return false; |
|
event = slot.event; |
|
slot.sequence.store(readPosition + kCapacity, std::memory_order_release); |
|
++readPosition; |
|
return true; |
|
} |
|
|
|
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"; |
|
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; |
|
uint64_t playbackBlocks = 0, playbackFrames = 0, playbackMeasured = 0; |
|
int64_t playbackMinLatency = 0, playbackMaxLatency = 0, playbackMaxConverter = 0, playbackMaxBlock = 0; |
|
}; |
|
|
|
void consume(const Event& e, std::map<uintptr_t, Device>& devices) { |
|
if (e.kind == AUDIO_DIAG_LOG) { |
|
// Hole учитывается кадрами в read-ветке; строка на каждый hole засоряет лог. |
|
if (std::strstr(e.text, "Hole.")) return; |
|
std::string message(e.text); |
|
while (!message.empty() && (message.back() == '\n' || message.back() == '\r')) message.pop_back(); |
|
if (e.value == 1) DEBUG_ERROR(DEBUG_CATEGORY_CALL, "AudioDiag: miniaudio log=%p %s", (void*)e.device, message.c_str()); |
|
else if (e.value == 2) DEBUG_WARN(DEBUG_CATEGORY_CALL, "AudioDiag: miniaudio log=%p level=%lld %s", |
|
(void*)e.device, (long long)e.value, message.c_str()); |
|
else if (e.value == 3) DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "AudioDiag: miniaudio log=%p %s", (void*)e.device, message.c_str()); |
|
else DEBUG_TRACE(DEBUG_CATEGORY_CALL, "AudioDiag: miniaudio log=%p %s", (void*)e.device, message.c_str()); |
|
return; |
|
} |
|
if (e.kind == AUDIO_DIAG_CLOSE) { |
|
DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: close dev=%p mono_ms=%llu", (void*)e.device, (unsigned long long)(e.wall / 1000000)); |
|
devices.erase(e.device); |
|
return; |
|
} |
|
auto& d = devices[e.device]; |
|
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_PLAYBACK_CLOCK) { |
|
const auto& p = e.playback; |
|
++d.playbackBlocks; d.playbackFrames += p.frames; |
|
if (p.rate) d.playbackMaxBlock = std::max(d.playbackMaxBlock, int64_t(p.frames) * 1000000 / p.rate); |
|
d.playbackMaxConverter = std::max(d.playbackMaxConverter, p.converter_us); |
|
if (p.measured) { |
|
if (!d.playbackMeasured) d.playbackMinLatency = d.playbackMaxLatency = p.latency_us; |
|
++d.playbackMeasured; |
|
d.playbackMinLatency = std::min(d.playbackMinLatency, p.latency_us); |
|
d.playbackMaxLatency = std::max(d.playbackMaxLatency, p.latency_us); |
|
} |
|
} 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) { |
|
DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: open dev=%p type=%lld rate=%lld mono_ms=%llu", (void*)e.device, |
|
(long long)e.value, (long long)e.detail, (unsigned long long)(e.wall / 1000000)); |
|
} else if (e.kind == AUDIO_DIAG_BACKEND_STARTED) { |
|
DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: backend playback started/resumed dev=%p mono_ms=%llu", |
|
(void*)e.device, (unsigned long long)(e.wall / 1000000)); |
|
} else if (e.kind == AUDIO_DIAG_NOTIFY) { |
|
DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: notification dev=%p type=%lld state=%lld mono_ms=%llu", (void*)e.device, |
|
(long long)e.value, (long long)e.detail, (unsigned long long)(e.wall / 1000000)); |
|
} else if (e.kind == AUDIO_DIAG_ENTER && e.stage >= 0 && e.stage < AUDIO_DIAG_STAGE_COUNT) { |
|
auto& s = d.stages[e.stage]; |
|
s.input = e.detail; |
|
if (s.last && e.wall >= s.last) s.maxGap = std::max(s.maxGap, e.wall - s.last); |
|
s.last = s.entered = e.wall; s.cpu = e.cpu; s.tid = e.tid; |
|
++s.calls; |
|
if (e.value > 0) s.frames += uint64_t(e.value); |
|
} else if (e.kind == AUDIO_DIAG_LEAVE && e.stage >= 0 && e.stage < AUDIO_DIAG_STAGE_COUNT) { |
|
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); |
|
} |
|
s.output = e.detail; |
|
s.entered = 0; |
|
} else if (e.kind >= AUDIO_DIAG_HOLE && e.kind <= AUDIO_DIAG_ERROR) { |
|
d.faults[e.kind] += uint64_t(std::max<int64_t>(e.value, 1)); |
|
// Первая аномалия за окно, остальные попадут в сводку. |
|
if (d.faults[e.kind] == uint64_t(std::max<int64_t>(e.value, 1))) |
|
DEBUG_WARN(DEBUG_CATEGORY_CALL, |
|
"AudioDiag: fault dev=%p role=%s id=%016llx kind=%s stage=%s value=%lld detail=%lld tid=%ld mono_ms=%llu", |
|
(void*)e.device, d.label.c_str(), (unsigned long long)d.id, kFaults[e.kind - AUDIO_DIAG_HOLE], |
|
e.stage >= 0 && e.stage < AUDIO_DIAG_STAGE_COUNT ? kStages[e.stage] : "none", |
|
(long long)e.value, (long long)e.detail, e.tid, (unsigned long long)(e.wall / 1000000)); |
|
} |
|
} |
|
|
|
void report(std::map<uintptr_t, Device>& devices, uint64_t wall, double elapsed) { |
|
const auto dropped = lost.exchange(0, std::memory_order_relaxed); |
|
if (dropped) DEBUG_WARN(DEBUG_CATEGORY_CALL, "AudioDiag: diagnostic events lost=%llu; interval is incomplete", |
|
(unsigned long long)dropped); |
|
std::set<long> stalledThreads; |
|
for (auto& [key, d] : devices) { |
|
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 converter_max_us=%lld block_max_us=%lld", |
|
(void*)key, d.label.c_str(), (unsigned long long)d.playbackBlocks, (unsigned long long)d.playbackFrames, |
|
(unsigned long long)d.playbackMeasured, (long long)d.playbackMinLatency, (long long)d.playbackMaxLatency, |
|
(long long)d.playbackMaxConverter, (long long)d.playbackMaxBlock); |
|
d.playbackBlocks = d.playbackFrames = d.playbackMeasured = 0; |
|
d.playbackMinLatency = d.playbackMaxLatency = d.playbackMaxConverter = d.playbackMaxBlock = 0; |
|
} |
|
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; |
|
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; |
|
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: %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)); |
|
s.calls = s.frames = s.maxGap = s.maxWork = s.maxCpu = 0; |
|
} |
|
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: 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], |
|
(unsigned long long)d.faults[AUDIO_DIAG_BACKEND_UNDERRUN], |
|
(unsigned long long)d.faults[AUDIO_DIAG_BACKEND_OVERFLOW], (unsigned long long)d.faults[AUDIO_DIAG_ERROR]); |
|
d.faults.fill(0); |
|
} |
|
for (auto tid : stalledThreads) { |
|
const auto path = std::string("/proc/self/task/") + std::to_string(tid) + "/"; |
|
std::ifstream waitFile(path + "wchan"), schedFile(path + "schedstat"); |
|
std::string wait; |
|
uint64_t cpu = 0, ready = 0, slices = 0; |
|
if (waitFile >> wait && schedFile >> cpu >> ready >> slices) |
|
DEBUG_WARN(DEBUG_CATEGORY_CALL, "AudioDiag: thread tid=%ld wchan=%s cpu_total=%.2fms ready_wait_total=%.2fms slices=%llu", |
|
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); |
|
} |
|
} |
|
|
|
void run() { |
|
std::map<uintptr_t, Device> devices; |
|
auto lastReport = now(CLOCK_MONOTONIC); |
|
for (;;) { |
|
Event e; |
|
for (uint64_t n = 0; n < kCapacity && take(e); ++n) consume(e, devices); |
|
const auto wall = now(CLOCK_MONOTONIC); |
|
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); |
|
} |
|
} // namespace |
|
|
|
void audio_diag_start(void) { |
|
if (running.load()) return; |
|
writePosition = 0; readPosition = 0; lost = 0; |
|
for (uint64_t i = 0; i < kCapacity; ++i) queue[i].sequence.store(i, std::memory_order_relaxed); |
|
running.store(true, std::memory_order_release); |
|
try { reporter = std::thread(run); } |
|
catch (const std::system_error& e) { |
|
running = false; |
|
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; timestamps=CLOCK_MONOTONIC", |
|
(unsigned long long)kCapacity); |
|
} |
|
void audio_diag_stop(void) { |
|
if (!running.exchange(false, std::memory_order_acq_rel)) return; |
|
reporter.join(); |
|
DEBUG_INFO(DEBUG_CATEGORY_CALL, "AudioDiag: stopped"); |
|
} |
|
void audio_diag_event(const void* device, int kind, int stage, int64_t value, int64_t detail) { |
|
publish(device, kind, stage, value, detail, nullptr); |
|
} |
|
void audio_diag_label(const void* device, uint64_t id, const char* name) { |
|
publish(device, AUDIO_DIAG_LABEL, -1, int64_t(id), 0, 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); |
|
} |
|
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); |
|
} |
|
#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*) {} |
|
void audio_diag_playback_clock(const void*, const audio_playback_timing*) {} |
|
#endif
|
|
|