From 4cc7d5eaf4dfbca895d69333a599c13a1401f6fb Mon Sep 17 00:00:00 2001 From: evgeny Date: Thu, 15 Oct 2026 11:38:47 +0200 Subject: [PATCH] Report call audio processing and send queue timing --- src/call/call.c | 12 ++++++++++++ src/call/call_audio.c | 24 ++++++++++++++++++++++++ 2 files changed, 36 insertions(+) diff --git a/src/call/call.c b/src/call/call.c index 5d88c449..5b06e652 100644 --- a/src/call/call.c +++ b/src/call/call.c @@ -446,6 +446,15 @@ static void call_post_stats(struct call_session* s) { etcp_router_conn_get(ctx->inst, s->group_id, s->peer_node_id, ETCP_RT_ID_CALL_AUDIO); if (rconn && rconn->recv_conn) rtt_tb = rconn->recv_conn->rtt_last; uint16_t rtt = rtt_tb / 10; /* ETCP хранит RTT в 0.1мс; CALL_STATS передаёт миллисекунды. */ + uint32_t oldest_ms = 0; + if (s->tx_q && s->tx_q->head) { + struct call_pkt_media oldest; memcpy(&oldest, s->tx_q->head->dgram + 1, sizeof(oldest)); + oldest_ms = (uint32_t)(get_time_tb() / 10) - oldest.ts_ms; + } + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "call audio TX queue id=%016llx drained=%u queued=%zu oldest_ms=%u wait_avg_max_ms=%llu/%u", + (unsigned long long)s->call_id, s->tx_wait_frames, s->tx_q ? (size_t)queue_entry_count(s->tx_q) : 0, oldest_ms, + (unsigned long long)(s->tx_wait_frames ? s->tx_wait_total_ms / s->tx_wait_frames : 0), s->tx_wait_max_ms); + s->tx_wait_frames = s->tx_wait_max_ms = 0; s->tx_wait_total_ms = 0; DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "%s: stats id=%016llx recv_peer=%016llx rtt_tb=%u rtt_ms=%u buffer=%dms tempo=%d dropped=%u underruns=%u", CALL_ID, (unsigned long long)s->call_id, (unsigned long long)(rconn && rconn->recv_conn ? rconn->recv_conn->peer_node_id : 0), @@ -824,6 +833,9 @@ static void call_tx_flush(struct call_session* s) { } struct ll_entry* e = queue_data_get(s->tx_q); struct call_pkt_media packet; memcpy(&packet, e->dgram + 1, sizeof(packet)); + uint32_t wait_ms = (uint32_t)(get_time_tb() / 10) - packet.ts_ms; + ++s->tx_wait_frames; s->tx_wait_total_ms += wait_ms; + if (wait_ms > s->tx_wait_max_ms) s->tx_wait_max_ms = wait_ms; if (etcp_route_send(ctx->inst, s->group_id, s->peer_node_id, e, 1, 0) == 0) { s->c_tx_frames++; if (packet.capture_pts_us != INT64_MIN) call_video_audio_sent(s, packet.capture_pts_us + 20000); diff --git a/src/call/call_audio.c b/src/call/call_audio.c index 3e865189..cf8e27d3 100644 --- a/src/call/call_audio.c +++ b/src/call/call_audio.c @@ -56,6 +56,14 @@ static unsigned int g_tx_reasons; static int g_tx_encode_error; static uint32_t g_aec_reported_over, g_aec_reported_under, g_pcm_events; +/* Секундные суммы под g_mtx; длительности локальные, без сравнения с удалёнными PTS. */ +struct call_audio_duration { uint64_t count, total_us, max_us; }; +static struct call_audio_duration g_feed_lock_time, g_process_time, g_post_time; +static void call_audio_duration_add(struct call_audio_duration* d, uint64_t us) { + ++d->count; d->total_us += us; + if (us > d->max_us) d->max_us = us; +} + /* Task и данные — одна аллокация; uasync освобождает task после callback и при destroy. */ struct call_audio_tx { struct posted_task task; @@ -70,6 +78,7 @@ static void call_audio_send(void* arg) { struct call_audio_tx* tx = arg; pthread_mutex_lock(&g_mtx); int current = tx->generation == g_tx_generation; + if (current) call_audio_duration_add(&g_post_time, (get_time_tb() - tx->created_tb) * 100); if (g_tx_pending) --g_tx_pending; int send = current && g_active && !g_ending && g_inst == tx->inst && g_call_id == tx->call_id; if (get_time_tb() - tx->created_tb > 2000) { @@ -231,6 +240,7 @@ static int call_audio_start_impl(uint64_t call_id, int prepared) { ++g_tx_generation; g_tx_dropped = g_tx_reported = 0; g_capture_epoch = 1; g_capture_end = INT64_MIN; g_codec_delay = codec_delay; g_tx_reasons = 0; g_tx_encode_error = 0; + g_feed_lock_time = g_process_time = g_post_time = (struct call_audio_duration){0}; g_ending = 0; g_ended_started = 0; g_glitch_started = 0; @@ -380,7 +390,9 @@ static int call_audio_feed_impl(uint64_t call_id, const int16_t* pcm, int count, struct UTUN_INSTANCE* inst = NULL; int len = -1; + uint64_t entered_us = get_time_us(); pthread_mutex_lock(&g_mtx); + uint64_t locked_us = get_time_us(); if (!g_active || call_id != g_call_id || !g_encoder) { pthread_mutex_unlock(&g_mtx); return -1; @@ -418,6 +430,8 @@ static int call_audio_feed_impl(uint64_t call_id, const int16_t* pcm, int count, tx = amplified; } else if (muted) { memset(amplified, 0, sizeof(amplified)); tx = amplified; } len = opus_codec_encode(g_encoder, tx, count, opus, (int)sizeof(opus)); + call_audio_duration_add(&g_feed_lock_time, locked_us - entered_us); + call_audio_duration_add(&g_process_time, get_time_us() - locked_us); ua = g_inst ? g_inst->ua : NULL; inst = g_inst; if (len <= 0 || !ua || !inst || g_ending || g_tx_pending >= 8) { @@ -578,6 +592,7 @@ int call_audio_get_stats(uint64_t call_id, int* buffer_ms, int* tempo_x100, unsigned int reasons = 0; int encode_error = 0; int tx_changed = 0, aec_changed = 0; + struct call_audio_duration lock_time = {0}, process_time = {0}, post_time = {0}; pthread_mutex_lock(&g_mtx); if (g_active && call_id == g_call_id && g_vj) { call_jitter_get_stats(g_vj, buffer_ms, tempo_x100, dropped, underruns, range); @@ -589,9 +604,18 @@ int call_audio_get_stats(uint64_t call_id, int* buffer_ms, int* tempo_x100, tx_changed = tx_dropped != g_tx_reported; g_tx_reported = tx_dropped; reasons = g_tx_reasons; g_tx_reasons = 0; encode_error = g_tx_encode_error; events = g_pcm_events; g_pcm_events = 0; + lock_time = g_feed_lock_time; process_time = g_process_time; post_time = g_post_time; + g_feed_lock_time = g_process_time = g_post_time = (struct call_audio_duration){0}; ok = 1; } pthread_mutex_unlock(&g_mtx); + if (lock_time.count || post_time.count) + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "call audio TX timing call=%llu frames=%llu posts=%llu " + "lock_avg_max_us=%llu/%llu process_avg_max_us=%llu/%llu post_avg_max_us=%llu/%llu pending=%u", + (unsigned long long)call_id, (unsigned long long)lock_time.count, (unsigned long long)post_time.count, + (unsigned long long)(lock_time.count ? lock_time.total_us / lock_time.count : 0), (unsigned long long)lock_time.max_us, + (unsigned long long)(process_time.count ? process_time.total_us / process_time.count : 0), (unsigned long long)process_time.max_us, + (unsigned long long)(post_time.count ? post_time.total_us / post_time.count : 0), (unsigned long long)post_time.max_us, tx_pending); if (tx_changed) DEBUG_WARN(DEBUG_CATEGORY_CALL, "%s: TX dropped=%u pending=%u limit=8 max_age=200ms reasons=queue:%d alloc:%d core:%d encode:%d age:%d ending:%d encode_result=%d", CALL_AUDIO_ID, tx_dropped, tx_pending, !!(reasons & 1), !!(reasons & 2), !!(reasons & 4),