From patchwork Tue May 23 13:58:41 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Anton Khirnov X-Patchwork-Id: 41806 Delivered-To: ffmpegpatchwork2@gmail.com Received: by 2002:a05:6a20:c51c:b0:10c:5e6f:955f with SMTP id gm28csp602226pzb; Tue, 23 May 2023 07:01:37 -0700 (PDT) X-Google-Smtp-Source: ACHHUZ5FTds4FMyI8RsnlRd1nsigiB80DUjksLcoP8qjQ/kiwRQfSE81mEc/IWIEjulC/8Nx96My X-Received: by 2002:a17:907:86a2:b0:96f:a39c:86d6 with SMTP id qa34-20020a17090786a200b0096fa39c86d6mr10956699ejc.8.1684850497542; Tue, 23 May 2023 07:01:37 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1684850497; cv=none; d=google.com; s=arc-20160816; b=py5d5pyfhsEA+8mbnKF3fFmJZETp/ZPtyeS9WqOzMgMAn3QBFLSYIKrKljXG/UL8Wi T+F9rQ5yN5dVGO0iW40vLFFfglPr34pwoHe7l9HkwyhUq+i7fHfRXQRfyisgT0u7CRuP xMc8Ocs2oUo+ZyUu6oSFeVpNaY+z0uGr+PPkx7XwIXH6UYkahPTIF/8si4bL+zvazfTn tPyAxn5nytgmwDQpUd9vPbmoWQY7htzyttpIXogvzrISCv1o49WM7HsUo9JPtlrD92nb 1fui/T5tBOdFS/HEMTNhpQPplL4TZ8IZAgj5ewG7nR7+52xafqoGCfcvbxH/3hvA/vm+ HiUQ== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=sender:errors-to:content-transfer-encoding:reply-to:list-subscribe :list-help:list-post:list-archive:list-unsubscribe:list-id :precedence:subject:mime-version:references:in-reply-to:message-id :date:to:from:delivered-to; bh=2ZsOOJAW84Y6rUk34aXOXzIiwo101r1zCnqVt11jy1Q=; b=Qakod+GNXbHfbvpqykdu7RcIQB0rrw0WD3hn/RlzUwXZecMLJqUQvFbcBg0bCVe2TK vcE+wMeY/3Wm8XMifumOcZmsGEeLe5JJkqfXI3BI6P35327gTOuz+943DsqZMR3DB+K4 wvHfrm0hCABvJSCQxOupdUxlWwXhSDR0XKZ5GSXbnt3nuRdGHcYTCM3RJrNIo8MaLwOv Z/ORzsUGlxdZZ5fbJ6pvybPACjoiQ+XrgBt/CiyNZDDK1jtlCfj151ftSGgvsvEGKhyu 68Z9wJ9IndQ1ypwT/uREY9V+YMVXie1uOF8P9md18M0/ckXk19pcuEGe2LI1u/qN6Sww gxOQ== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of ffmpeg-devel-bounces@ffmpeg.org designates 79.124.17.100 as permitted sender) smtp.mailfrom=ffmpeg-devel-bounces@ffmpeg.org Return-Path: Received: from ffbox0-bg.mplayerhq.hu (ffbox0-bg.ffmpeg.org. [79.124.17.100]) by mx.google.com with ESMTP id gv39-20020a1709072be700b0096f75d92716si1609987ejc.752.2023.05.23.07.01.32; Tue, 23 May 2023 07:01:37 -0700 (PDT) Received-SPF: pass (google.com: domain of ffmpeg-devel-bounces@ffmpeg.org designates 79.124.17.100 as permitted sender) client-ip=79.124.17.100; Authentication-Results: mx.google.com; spf=pass (google.com: domain of ffmpeg-devel-bounces@ffmpeg.org designates 79.124.17.100 as permitted sender) smtp.mailfrom=ffmpeg-devel-bounces@ffmpeg.org Received: from [127.0.1.1] (localhost [127.0.0.1]) by ffbox0-bg.mplayerhq.hu (Postfix) with ESMTP id 559D668C175; Tue, 23 May 2023 16:59:17 +0300 (EEST) X-Original-To: ffmpeg-devel@ffmpeg.org Delivered-To: ffmpeg-devel@ffmpeg.org Received: from mail0.khirnov.net (red.khirnov.net [176.97.15.12]) by ffbox0-bg.mplayerhq.hu (Postfix) with ESMTPS id 83A0B68C126 for ; Tue, 23 May 2023 16:59:03 +0300 (EEST) Received: from localhost (localhost [IPv6:::1]) by mail0.khirnov.net (Postfix) with ESMTP id EA4DE2406CD for ; Tue, 23 May 2023 15:59:01 +0200 (CEST) Received: from mail0.khirnov.net ([IPv6:::1]) by localhost (mail0.khirnov.net [IPv6:::1]) (amavisd-new, port 10024) with ESMTP id RZD5NvqpIFqc for ; Tue, 23 May 2023 15:59:01 +0200 (CEST) Received: from libav.khirnov.net (libav.khirnov.net [IPv6:2a00:c500:561:201::7]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256 client-signature RSA-PSS (2048 bits) client-digest SHA256) (Client CN "libav.khirnov.net", Issuer "smtp.khirnov.net SMTP CA" (verified OK)) by mail0.khirnov.net (Postfix) with ESMTPS id C16712406CE for ; Tue, 23 May 2023 15:58:48 +0200 (CEST) Received: from libav.khirnov.net (libav.khirnov.net [IPv6:::1]) by libav.khirnov.net (Postfix) with ESMTP id B2C213A048F for ; Tue, 23 May 2023 15:58:48 +0200 (CEST) From: Anton Khirnov To: ffmpeg-devel@ffmpeg.org Date: Tue, 23 May 2023 15:58:41 +0200 Message-Id: <20230523135842.20388-14-anton@khirnov.net> X-Mailer: git-send-email 2.39.2 In-Reply-To: <20230523135842.20388-1-anton@khirnov.net> References: <20230523135842.20388-1-anton@khirnov.net> MIME-Version: 1.0 Subject: [FFmpeg-devel] [PATCH 14/15] fftools/sync_queue: add debug logging X-BeenThere: ffmpeg-devel@ffmpeg.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: FFmpeg development discussions and patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Reply-To: FFmpeg development discussions and patches Errors-To: ffmpeg-devel-bounces@ffmpeg.org Sender: "ffmpeg-devel" X-TUID: XdwdX7uVIWYX --- 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); /**