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.
253 lines
13 KiB
253 lines
13 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]; |
|
}; |
|
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) { |
|
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); |
|
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; |
|
}; |
|
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{}; |
|
}; |
|
|
|
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_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) { |
|
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 auto level = s.maxWork > 50000000 || s.maxGap > 50000000 || pending > 50 || idle > 100 |
|
? DEBUG_LEVEL_WARN : DEBUG_LEVEL_DEBUG; |
|
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 " |
|
"gap_max=%.2fms work_max=%.2fms cpu_max=%.2fms pending=%.2fms since_enter=%.2fms in_detail=%lld out_detail=%lld mono_ms=%llu", |
|
(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: 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, |
|
(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 reporting=1s category=call; 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); |
|
} |
|
#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*) {} |
|
#endif
|
|
|