diff --git a/src/call/call_video_playout.c b/src/call/call_video_playout.c index 3683693b..42f0a073 100644 --- a/src/call/call_video_playout.c +++ b/src/call/call_video_playout.c @@ -26,10 +26,30 @@ void call_video_playout_init(struct call_video_playout *p, uint64_t call_id) { (unsigned long long)call_id, VIDEO_MAX_SPEED_PPM, VIDEO_AHEAD_US); } -/* Сводка агрегирует штатные ожидания и пропуски; per-frame spam не нужен. */ -static void report(struct call_video_playout *p, int64_t now) { - if (!p->report_us) p->report_us = now; - if (now - p->report_us < 1000000) return; +void call_video_playout_log_event(const struct call_video_playout_event *event) { + const struct call_video_playout *p = &event->state; + const struct call_video_playout_frame *f = &event->frame; + int64_t now = event->now_us; + if (event->kind == CALL_VIDEO_LOG_CLOCK) { + DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video playout clock call=%llu valid=%d pts=%lld", + (unsigned long long)p->call_id, p->audio_valid, (long long)f->pts_us); return; + } + if (event->kind == CALL_VIDEO_LOG_ORDER) { + DEBUG_WARN(DEBUG_CATEGORY_CALL, "video playout invalid/order call=%llu pts=%lld last=%lld received=%lld now=%lld interval_us=%u", + (unsigned long long)p->call_id, (long long)f->pts_us, (long long)p->last_pts, + (long long)f->received_us, (long long)now, f->interval_us); return; + } + if (event->kind == CALL_VIDEO_LOG_GAP) { + DEBUG_WARN(DEBUG_CATEGORY_CALL, + "video source gap call=%llu pts_delta_us=%lld interval_us=%u av_us=%lld display_step_us=%lld; no extra gap wait", + (unsigned long long)p->call_id, (long long)(f->pts_us - p->last_pts), f->interval_us, + (long long)p->pending_av, (long long)((int64_t)f->interval_us * 1000000 / p->speed_ppm)); return; + } + if (event->kind == CALL_VIDEO_LOG_ACK) { + DEBUG_WARN(DEBUG_CATEGORY_CALL, "video presentation ACK rejected call=%llu pts=%lld expected=%lld awaiting=%d now=%lld selected=%lld", + (unsigned long long)p->call_id, (long long)f->pts_us, (long long)p->pending.pts_us, p->awaiting, + (long long)now, (long long)p->selected_us); return; + } DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video playout call=%llu interval_us=%lld shown=%u speed_ppm=%u drop_order=%u " "cadence_us=%lld..%lld gap_pts_us=%lld gap_rx_us=%lld gap_dispatch_us=%lld " @@ -41,6 +61,21 @@ static void report(struct call_video_playout *p, int64_t now) { (long long)(p->shown ? p->av_min : 0), (long long)(p->shown ? p->av_max : 0), (long long)p->dispatch_max, (long long)p->data_shift, p->audio_wait, p->clock_wait, p->source_gaps, (long long)p->source_gap_max, p->queued, p->reserve, p->awaiting, (long long)p->lead_us); +} + +static void log_event(struct call_video_playout *p, enum call_video_playout_event_kind kind, + const struct call_video_playout_frame *frame, int64_t now) { + struct call_video_playout_event event = {.kind = kind, .state = *p, .now_us = now}; + if (frame) event.frame = *frame; + if (p->log_event) p->log_event(p->log_arg, &event); + else call_video_playout_log_event(&event); +} + +/* Сводка агрегирует штатные ожидания; timer лишь копирует событие в ограниченную очередь. */ +static void report(struct call_video_playout *p, int64_t now) { + if (!p->report_us) p->report_us = now; + if (now - p->report_us < 1000000) return; + log_event(p, CALL_VIDEO_LOG_REPORT, NULL, now); p->report_us = now; p->shown = p->order = p->audio_wait = p->clock_wait = 0; p->interval_min = p->av_min = INT64_MAX; p->av_max = INT64_MIN; p->interval_max = p->dispatch_max = p->data_shift = 0; @@ -56,18 +91,16 @@ enum call_video_playout_action call_video_playout_poll(struct call_video_playout p->queued = queued; p->reserve = reserve; report(p, now); p->deadline_us = now + 5000; if (p->audio_valid != !!audio_valid) { - DEBUG_DEBUG(DEBUG_CATEGORY_CALL, "video playout clock call=%llu valid=%d pts=%lld", - (unsigned long long)p->call_id, !!audio_valid, (long long)audio); p->audio_valid = !!audio_valid; + struct call_video_playout_frame changed = {.pts_us = audio}; + log_event(p, CALL_VIDEO_LOG_CLOCK, &changed, now); } if (!audio_valid) { p->head_pts = -1; p->clock_wait++; return CALL_VIDEO_PLAYOUT_WAIT; } // Пустой FIFO не означает разрыв часов; срок сохраняется до появления следующей головы. if (!f || p->awaiting) return CALL_VIDEO_PLAYOUT_WAIT; if (f->pts_us <= p->last_pts || f->received_us < 0 || f->received_us > now || f->interval_us < 16666 || f->interval_us > 1000000) { - DEBUG_WARN(DEBUG_CATEGORY_CALL, "video playout invalid/order call=%llu pts=%lld last=%lld received=%lld now=%lld interval_us=%u", - (unsigned long long)p->call_id, (long long)f->pts_us, (long long)p->last_pts, - (long long)f->received_us, (long long)now, f->interval_us); + log_event(p, CALL_VIDEO_LOG_ORDER, f, now); p->order++; return CALL_VIDEO_PLAYOUT_DROP_ORDER; } // Небольшой рабочий запас сохраняем; ускорение снимает избыток всего конвейера, а не только decoded FIFO. @@ -99,9 +132,8 @@ enum call_video_playout_action call_video_playout_poll(struct call_video_playout } if (deadline > now) return CALL_VIDEO_PLAYOUT_WAIT; if (delta > (int64_t)f->interval_us * 3) { - if (!p->source_gaps) DEBUG_WARN(DEBUG_CATEGORY_CALL, - "video source gap call=%llu pts_delta_us=%lld interval_us=%u av_us=%lld display_step_us=%lld; no extra gap wait", - (unsigned long long)p->call_id, (long long)delta, f->interval_us, (long long)av, (long long)step); + p->pending_av = av; + if (!p->source_gaps) log_event(p, CALL_VIDEO_LOG_GAP, f, now); p->source_gaps++; if (delta > p->source_gap_max) p->source_gap_max = delta; } @@ -112,9 +144,8 @@ enum call_video_playout_action call_video_playout_poll(struct call_video_playout void call_video_playout_presented(struct call_video_playout *p, int64_t pts, int64_t now) { if (!p->awaiting || p->pending.pts_us != pts || now < p->selected_us) { - DEBUG_WARN(DEBUG_CATEGORY_CALL, "video presentation ACK rejected call=%llu pts=%lld expected=%lld awaiting=%d now=%lld selected=%lld", - (unsigned long long)p->call_id, (long long)pts, (long long)p->pending.pts_us, p->awaiting, - (long long)now, (long long)p->selected_us); return; + struct call_video_playout_frame rejected = {.pts_us = pts}; + log_event(p, CALL_VIDEO_LOG_ACK, &rejected, now); return; } const struct call_video_playout_frame *f = &p->pending; int64_t av = p->pending_av, lead = now - p->selected_us; diff --git a/src/call/call_video_playout.h b/src/call/call_video_playout.h index 20f9b891..6142c700 100644 --- a/src/call/call_video_playout.h +++ b/src/call/call_video_playout.h @@ -20,6 +20,7 @@ struct call_video_playout_frame { enum call_video_playout_action { CALL_VIDEO_PLAYOUT_WAIT, CALL_VIDEO_PLAYOUT_SHOW, CALL_VIDEO_PLAYOUT_DROP_ORDER }; +struct call_video_playout_event; struct call_video_playout { uint64_t call_id; int anchored, audio_valid; @@ -34,7 +35,21 @@ struct call_video_playout { int awaiting; int64_t selected_us, pending_av, head_pts, head_due_us, lead_us, rate_us; unsigned queued, reserve; // reserve — будущие кадры сверх головы, включая необходимый pipeline backend. + // NULL пишет DEBUG напрямую; timer устанавливает неблокирующий callback с копированием события. + void (*log_event)(void *, const struct call_video_playout_event *); + void *log_arg; }; +enum call_video_playout_event_kind { + CALL_VIDEO_LOG_REPORT, CALL_VIDEO_LOG_CLOCK, CALL_VIDEO_LOG_ORDER, CALL_VIDEO_LOG_GAP, CALL_VIDEO_LOG_ACK +}; +struct call_video_playout_event { + enum call_video_playout_event_kind kind; + struct call_video_playout state; // Снимок принадлежит событию, указатели logger не разыменовываются reporter. + struct call_video_playout_frame frame; + int64_t now_us; +}; +/* Reporter вне timer: форматирует и выводит сохранённое событие через DEBUG категории call. */ +void call_video_playout_log_event(const struct call_video_playout_event *event); int64_t call_video_playout_now_us(void); void call_video_playout_init(struct call_video_playout *p, uint64_t call_id);