Report call audio processing and send queue timing

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);

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),