diff --git a/src/call/call.c b/src/call/call.c index a53e235c..d17ea0b5 100644 --- a/src/call/call.c +++ b/src/call/call.c @@ -539,16 +539,6 @@ static void call_post_stats(struct call_session* s) { (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; - struct ETCP_ROUTER_TX_STATS net = {0}; - etcp_router_tx_stats(ctx->inst, s->group_id, s->peer_node_id, ETCP_RT_ID_CALL_AUDIO, get_time_us(), &net); - const char *wait = s->tx_q && s->tx_q->count < (int)s->audio_batch.target ? "frames" - : !s->audio_send.conn ? "unregistered" : net.no_route ? "no-route" : !net.ready ? "handshake" - : net.receive_busy ? "peer-busy" : rconn && net.inflight_packets >= rconn->inflight_limit ? "window" : "transport"; - DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "audio batch flow call=%llx target=%u wait=%s queued=%u/%llu inflight=%u/%llu " - "enqueue_ack_us=%llu submit_ack_us=%u ack_bytes_500ms=%llu tx_frames=%u tx_batches=%u rx_frames=%u rx_batches=%u", - (unsigned long long)s->call_id, s->audio_batch.target, wait, net.queued_packets, (unsigned long long)net.queued_age_us, - net.inflight_packets, (unsigned long long)net.inflight_age_us, (unsigned long long)net.delivery_rtt_us, - net.rtt_us, (unsigned long long)net.window.bytes, s->c_tx_frames, s->tx_batches, s->c_rx_frames, s->rx_batches); call_tx_flush(s); /* Повтор регистрации после reset/ошибки выделения; обычный drain работает по событиям. */ 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, @@ -1014,6 +1004,35 @@ static void call_audio_batch_tick(void* arg) { struct ETCP_ROUTER_TX_STATS net = {0}; uint64_t now = get_time_us(); int found = etcp_router_tx_stats(s->ctx->inst, s->group_id, s->peer_node_id, ETCP_RT_ID_CALL_AUDIO, now, &net) == 0; + if (now - s->buffer_log_us >= CALL_BUFFER_LOG_MS * 1000) { + uint64_t elapsed = s->buffer_log_us ? now - s->buffer_log_us : 0; s->buffer_log_us = now; + if (debug_should_output(DEBUG_LEVEL_DEBUG, DEBUG_CATEGORY_CALL)) { + struct ETCP_ROUTER_CONN* r = s->audio_send.conn; + uint64_t oldest_us = s->tx_q && s->tx_q->head + ? now - ((struct call_audio_pending*)s->tx_q->head->data)->created_us : 0; + const char* wait = !s->tx_q || !s->tx_q->count ? "empty" : s->tx_q->count < (int)s->audio_batch.target ? "frames" + : !found ? "no-channel" : net.no_route ? "no-route" : !net.ready ? "handshake" + : net.receive_busy ? "peer-busy" : r && net.inflight_packets >= r->inflight_limit ? "window" + : !r ? "unregistered" : "router-or-transport"; + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, + "audio transport call=%016llx mono_ms=%llu dt_ms=%llu batch=%u feedback=%d delay_ms=%.1f wait=%s " + "local_frames=%u local_B=%llu local_age_ms=%.1f router_found=%d ready=%d no_route=%d busy=%d probing=%d " + "queued_pkts_B=%u/%llu queued_age_ms=%.1f inflight_pkts_B=%u/%llu inflight_age_ms=%.1f " + "enqueue_ack_ms=%.1f submit_ack_ms=%.1f baseline_ms=%.1f ack_age_ms=%.1f ack_B_500ms=%llu " + "epochs=%llu/%llu tx_frames_batches=%u/%u rx_frames_batches=%u/%u tx_dropped_total=%u rx_idle_ms=%llu", + (unsigned long long)s->call_id, (unsigned long long)(now / 1000), (unsigned long long)(elapsed / 1000), + s->audio_batch.target, s->audio_batch.feedback_received, s->audio_batch.delay_us / 1000.0, wait, + s->tx_q ? (unsigned)s->tx_q->count : 0, (unsigned long long)(s->tx_q ? s->tx_q->total_bytes : 0), oldest_us / 1000.0, + found, net.ready, net.no_route, net.receive_busy, net.probing, + net.queued_packets, (unsigned long long)net.queued_bytes, net.queued_age_us / 1000.0, + net.inflight_packets, (unsigned long long)net.inflight_bytes, net.inflight_age_us / 1000.0, + net.delivery_rtt_us / 1000.0, net.rtt_us / 1000.0, net.baseline_rtt_us / 1000.0, + net.last_ack_us ? (now - net.last_ack_us) / 1000.0 : -1.0, (unsigned long long)net.window.bytes, + (unsigned long long)net.local_epoch, (unsigned long long)net.peer_epoch, + s->c_tx_frames, s->tx_batches, s->c_rx_frames, s->rx_batches, s->c_tx_dropped, + (unsigned long long)((get_time_tb() - s->last_media_tb) / 10)); + } + } const struct call_audio_ops* audio = s->ctx->inst->call_audio_ops; if (audio && audio->record_tx) { struct call_history_tx snapshot = {.at_ms = now / 1000, .queued_bytes = s->tx_q ? s->tx_q->total_bytes : 0}; diff --git a/src/call/call_priv.h b/src/call/call_priv.h index 4387a21b..7f5f4e48 100644 --- a/src/call/call_priv.h +++ b/src/call/call_priv.h @@ -37,6 +37,7 @@ struct call_session { uint16_t tx_media_seq; /* Следующий sequence аудиопакета с wrap uint16; расходуется до выделения TX entry. */ struct call_audio_batch_control audio_batch; /* Прежний адаптивный выбор обязательного числа кадров. */ void *audio_batch_timer; /* Снимок Router и пересчёт target каждые 50мс; не отправляет неполную пачку. */ + uint64_t buffer_log_us; /* Последняя сводка транспорта, монотонные мкс; период 200мс, без отдельного таймера. */ uint32_t tx_batches, rx_batches; /* Число Router-кодограмм, отдельно от аудиокадров. */ struct ll_queue *tx_q; /* FIFO Opus с локальными seq/PTS/created_us в entry->data; до 750, overflow удаляет голову. */ struct router_send_request audio_send; /* Слот отправки: до callback кадры остаются в tx_q. */