From e9a868e9eef5215b468244596e2103a3add7759f Mon Sep 17 00:00:00 2001 From: Anton Khirnov Date: Tue, 23 May 2023 15:45:37 +0200 Subject: [PATCH] fftools/sync_queue: add debug logging --- fftools/ffmpeg_mux_init.c | 4 ++-- fftools/sync_queue.c | 40 ++++++++++++++++++++++++++++++++++++--- fftools/sync_queue.h | 2 +- 3 files changed, 40 insertions(+), 6 deletions(-) diff --git a/fftools/ffmpeg_mux_init.c b/fftools/ffmpeg_mux_init.c index dc33d225df..7878789bb4 100644 --- a/fftools/ffmpeg_mux_init.c +++ b/fftools/ffmpeg_mux_init.c @@ -1625,7 +1625,7 @@ static int setup_sync_queues(Muxer *mux, AVFormatContext *oc, int64_t buf_size_u * - at least one audio encoder requires constant frame sizes */ if ((of->shortest && nb_av_enc > 1) || limit_frames_av_enc || nb_audio_fs) { - of->sq_encode = sq_alloc(SYNC_QUEUE_FRAMES, buf_size_us); + of->sq_encode = sq_alloc(SYNC_QUEUE_FRAMES, buf_size_us, mux); if (!of->sq_encode) return AVERROR(ENOMEM); @@ -1650,7 +1650,7 @@ static int setup_sync_queues(Muxer *mux, AVFormatContext *oc, int64_t buf_size_u /* if there are any additional interleaved streams, then ALL the streams * are also synchronized before sending them to the muxer */ if (nb_interleaved > nb_av_enc) { - mux->sq_mux = sq_alloc(SYNC_QUEUE_PACKETS, buf_size_us); + mux->sq_mux = sq_alloc(SYNC_QUEUE_PACKETS, buf_size_us, mux); if (!mux->sq_mux) return AVERROR(ENOMEM); diff --git a/fftools/sync_queue.c b/fftools/sync_queue.c index a7aac04047..c0f33e9235 100644 --- a/fftools/sync_queue.c +++ b/fftools/sync_queue.c @@ -27,6 +27,7 @@ #include "libavutil/mathematics.h" #include "libavutil/mem.h" #include "libavutil/samplefmt.h" +#include "libavutil/timestamp.h" #include "objpool.h" #include "sync_queue.h" @@ -87,6 +88,8 @@ typedef struct SyncQueueStream { struct SyncQueue { enum SyncQueueType type; + void *logctx; + /* no more frames will be sent for any stream */ int finished; /* sync head: the stream with the _smallest_ head timestamp @@ -169,6 +172,11 @@ static void finish_stream(SyncQueue *sq, unsigned int stream_idx) { SyncQueueStream *st = &sq->streams[stream_idx]; + if (!st->finished) + av_log(sq->logctx, AV_LOG_DEBUG, + "sq: finish %u; head ts %s\n", stream_idx, + av_ts2timestr(st->head_ts, &st->tb)); + st->finished = 1; if (st->limiting && st->head_ts != AV_NOPTS_VALUE) { @@ -186,8 +194,14 @@ static void finish_stream(SyncQueue *sq, unsigned int stream_idx) for (unsigned int i = 0; i < sq->nb_streams; i++) { SyncQueueStream *st1 = &sq->streams[i]; if (st != st1 && st1->head_ts != AV_NOPTS_VALUE && - av_compare_ts(st->head_ts, st->tb, st1->head_ts, st1->tb) <= 0) + av_compare_ts(st->head_ts, st->tb, st1->head_ts, st1->tb) <= 0) { + if (!st1->finished) + av_log(sq->logctx, AV_LOG_DEBUG, + "sq: finish secondary %u; head ts %s\n", i, + av_ts2timestr(st1->head_ts, &st1->tb)); + st1->finished = 1; + } } } @@ -197,6 +211,8 @@ static void finish_stream(SyncQueue *sq, unsigned int stream_idx) return; } sq->finished = 1; + + av_log(sq->logctx, AV_LOG_DEBUG, "sq: finish queue\n"); } static void queue_head_update(SyncQueue *sq) @@ -306,6 +322,9 @@ static int overflow_heartbeat(SyncQueue *sq, int stream_idx) if (st1->head_ts != AV_NOPTS_VALUE) ts = FFMAX(st1->head_ts + 1, ts); + av_log(sq->logctx, AV_LOG_DEBUG, "sq: %u overflow heardbeat %s -> %s\n", + i, av_ts2timestr(st1->head_ts, &st1->tb), av_ts2timestr(ts, &st1->tb)); + stream_update_ts(sq, i, ts); } @@ -323,6 +342,7 @@ int sq_send(SyncQueue *sq, unsigned int stream_idx, SyncQueueFrame frame) st = &sq->streams[stream_idx]; if (frame_null(sq, frame)) { + av_log(sq->logctx, AV_LOG_DEBUG, "sq: %u EOF\n", stream_idx); finish_stream(sq, stream_idx); return 0; } @@ -347,6 +367,9 @@ int sq_send(SyncQueue *sq, unsigned int stream_idx, SyncQueueFrame frame) ts = frame_end(sq, dst, 0); + av_log(sq->logctx, AV_LOG_DEBUG, "sq: send %u ts %s\n", stream_idx, + av_ts2timestr(ts, &st->tb)); + ret = av_fifo_write(st->fifo, &dst, 1); if (ret < 0) { frame_move(sq, frame, dst); @@ -364,8 +387,12 @@ int sq_send(SyncQueue *sq, unsigned int stream_idx, SyncQueueFrame frame) else st->frames_sent++; - if (st->frames_sent >= st->frames_max) + if (st->frames_sent >= st->frames_max) { + av_log(sq->logctx, AV_LOG_DEBUG, "sq: %u frames_max %"PRIu64" reached\n", + stream_idx, st->frames_max); + finish_stream(sq, stream_idx); + } return 0; } @@ -531,6 +558,12 @@ static int receive_for_stream(SyncQueue *sq, unsigned int stream_idx, st->samples_queued -= frame_samples(sq, frame); } + av_log(sq->logctx, AV_LOG_DEBUG, + "sq: receive %u ts %s queue head %d ts %s\n", stream_idx, + av_ts2timestr(frame_end(sq, frame, 0), &st->tb), + sq->head_stream, + st_head ? av_ts2timestr(st_head->head_ts, &st_head->tb) : "N/A"); + return 0; } } @@ -630,7 +663,7 @@ void sq_frame_samples(SyncQueue *sq, unsigned int stream_idx, sq->align_mask = av_cpu_max_align() - 1; } -SyncQueue *sq_alloc(enum SyncQueueType type, int64_t buf_size_us) +SyncQueue *sq_alloc(enum SyncQueueType type, int64_t buf_size_us, void *logctx) { SyncQueue *sq = av_mallocz(sizeof(*sq)); @@ -639,6 +672,7 @@ SyncQueue *sq_alloc(enum SyncQueueType type, int64_t buf_size_us) sq->type = type; sq->buf_size_us = buf_size_us; + sq->logctx = logctx; sq->head_stream = -1; sq->head_finished_stream = -1; diff --git a/fftools/sync_queue.h b/fftools/sync_queue.h index bc7cd42390..dc5acfd499 100644 --- a/fftools/sync_queue.h +++ b/fftools/sync_queue.h @@ -50,7 +50,7 @@ typedef struct SyncQueue SyncQueue; * * @param buf_size_us maximum duration that will be buffered in microseconds */ -SyncQueue *sq_alloc(enum SyncQueueType type, int64_t buf_size_us); +SyncQueue *sq_alloc(enum SyncQueueType type, int64_t buf_size_us, void *logctx); void sq_free(SyncQueue **sq); /**